Add useful experiment logs #48

Merged
0950726 merged 4 commits from feat/use-experiment-logs into dev 2026-01-27 17:45:42 +00:00
7 changed files with 87 additions and 17 deletions
Showing only changes of commit 43d81002ec - Show all commits

View File

@@ -1,4 +1,5 @@
import json import json
import logging
import zmq import zmq
import zmq.asyncio as azmq import zmq.asyncio as azmq
@@ -8,6 +9,8 @@ from control_backend.core.agent_system import InternalMessage
from control_backend.core.config import settings from control_backend.core.config import settings
from control_backend.schemas.ri_message import GestureCommand, RIEndpoint from control_backend.schemas.ri_message import GestureCommand, RIEndpoint
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class RobotGestureAgent(BaseAgent): class RobotGestureAgent(BaseAgent):
""" """
@@ -111,6 +114,7 @@ class RobotGestureAgent(BaseAgent):
gesture_command.data, gesture_command.data,
) )
return return
experiment_logger.action("Gesture: %s", gesture_command.data)
await self.pubsocket.send_json(gesture_command.model_dump()) await self.pubsocket.send_json(gesture_command.model_dump())
except Exception: except Exception:
self.logger.exception("Error processing internal message.") self.logger.exception("Error processing internal message.")

View File

@@ -1,6 +1,7 @@
import asyncio import asyncio
import copy import copy
import json import json
import logging
import time import time
from collections.abc import Iterable from collections.abc import Iterable
@@ -19,6 +20,9 @@ from control_backend.schemas.ri_message import GestureCommand, RIEndpoint, Speec
DELIMITER = ";\n" # TODO: temporary until we support lists in AgentSpeak DELIMITER = ";\n" # TODO: temporary until we support lists in AgentSpeak
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class BDICoreAgent(BaseAgent): class BDICoreAgent(BaseAgent):
""" """
BDI Core Agent. BDI Core Agent.
@@ -207,6 +211,9 @@ class BDICoreAgent(BaseAgent):
else: else:
term = agentspeak.Literal(name) term = agentspeak.Literal(name)
if name != "user_said":
experiment_logger.observation(f"Formed new belief: {name}{f'={args}' if args else ''}")
self.bdi_agent.call( self.bdi_agent.call(
agentspeak.Trigger.addition, agentspeak.Trigger.addition,
agentspeak.GoalType.belief, agentspeak.GoalType.belief,
@@ -244,6 +251,9 @@ class BDICoreAgent(BaseAgent):
new_args = (agentspeak.Literal(arg) for arg in args) new_args = (agentspeak.Literal(arg) for arg in args)
term = agentspeak.Literal(name, new_args) term = agentspeak.Literal(name, new_args)
if name != "user_said":
experiment_logger.observation(f"Removed belief: {name}{f'={args}' if args else ''}")
result = self.bdi_agent.call( result = self.bdi_agent.call(
agentspeak.Trigger.removal, agentspeak.Trigger.removal,
agentspeak.GoalType.belief, agentspeak.GoalType.belief,
@@ -386,6 +396,8 @@ class BDICoreAgent(BaseAgent):
body=str(message_text), body=str(message_text),
) )
experiment_logger.chat(str(message_text), extra={"role": "assistant"})
self.add_behavior(self.send(chat_history_message)) self.add_behavior(self.send(chat_history_message))
yield yield

View File

@@ -1,10 +1,12 @@
import asyncio import asyncio
import json import json
import logging
import zmq import zmq
from pydantic import ValidationError from pydantic import ValidationError
from zmq.asyncio import Context from zmq.asyncio import Context
import control_backend
from control_backend.agents import BaseAgent from control_backend.agents import BaseAgent
from control_backend.agents.bdi.agentspeak_generator import AgentSpeakGenerator from control_backend.agents.bdi.agentspeak_generator import AgentSpeakGenerator
from control_backend.core.config import settings from control_backend.core.config import settings
@@ -19,6 +21,8 @@ from control_backend.schemas.program import (
Program, Program,
) )
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class BDIProgramManager(BaseAgent): class BDIProgramManager(BaseAgent):
""" """
@@ -277,6 +281,18 @@ class BDIProgramManager(BaseAgent):
await self.send(extractor_msg) await self.send(extractor_msg)
self.logger.debug("Sent message to extractor agent to clear history.") self.logger.debug("Sent message to extractor agent to clear history.")
@staticmethod
def _rollover_experiment_logs():
"""
A new experiment program started; make a new experiment log file.
"""
handlers = logging.getLogger(settings.logging_settings.experiment_logger_name).handlers
for handler in handlers:
if isinstance(handler, control_backend.logging.DatedFileHandler):
experiment_logger.action("Doing rollover...")
handler.do_rollover()
experiment_logger.debug("Finished rollover.")
async def _receive_programs(self): async def _receive_programs(self):
""" """
Continuous loop that receives program updates from the HTTP endpoint. Continuous loop that receives program updates from the HTTP endpoint.
@@ -297,6 +313,7 @@ class BDIProgramManager(BaseAgent):
self._initialize_internal_state(program) self._initialize_internal_state(program)
await self._send_program_to_user_interrupt(program) await self._send_program_to_user_interrupt(program)
await self._send_clear_llm_history() await self._send_clear_llm_history()
self._rollover_experiment_logs()
await asyncio.gather( await asyncio.gather(
self._create_agentspeak_and_send_to_bdi(program), self._create_agentspeak_and_send_to_bdi(program),

View File

@@ -1,4 +1,5 @@
import json import json
import logging
import re import re
import uuid import uuid
from collections.abc import AsyncGenerator from collections.abc import AsyncGenerator
@@ -13,6 +14,8 @@ from control_backend.core.config import settings
from ...schemas.llm_prompt_message import LLMPromptMessage from ...schemas.llm_prompt_message import LLMPromptMessage
from .llm_instructions import LLMInstructions from .llm_instructions import LLMInstructions
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class LLMAgent(BaseAgent): class LLMAgent(BaseAgent):
""" """
@@ -132,7 +135,7 @@ class LLMAgent(BaseAgent):
*self.history, *self.history,
] ]
message_id = str(uuid.uuid4()) # noqa message_id = str(uuid.uuid4())
try: try:
full_message = "" full_message = ""
@@ -141,10 +144,9 @@ class LLMAgent(BaseAgent):
full_message += token full_message += token
current_chunk += token current_chunk += token
self.logger.llm( experiment_logger.chat(
"Received token: %s",
full_message, full_message,
extra={"reference": message_id}, # Used in the UI to update old logs extra={"role": "assistant", "reference": message_id, "partial": True},
) )
# Stream the message in chunks separated by punctuation. # Stream the message in chunks separated by punctuation.
@@ -160,6 +162,11 @@ class LLMAgent(BaseAgent):
if current_chunk: if current_chunk:
yield current_chunk yield current_chunk
experiment_logger.chat(
full_message,
extra={"role": "assistant", "reference": message_id, "partial": False},
)
self.history.append( self.history.append(
{ {
"role": "assistant", "role": "assistant",

View File

@@ -1,4 +1,5 @@
import asyncio import asyncio
import logging
import numpy as np import numpy as np
import zmq import zmq
@@ -10,6 +11,8 @@ from control_backend.core.config import settings
from .speech_recognizer import SpeechRecognizer from .speech_recognizer import SpeechRecognizer
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class TranscriptionAgent(BaseAgent): class TranscriptionAgent(BaseAgent):
""" """
@@ -25,6 +28,8 @@ class TranscriptionAgent(BaseAgent):
:ivar audio_in_socket: The ZMQ SUB socket instance. :ivar audio_in_socket: The ZMQ SUB socket instance.
:ivar speech_recognizer: The speech recognition engine instance. :ivar speech_recognizer: The speech recognition engine instance.
:ivar _concurrency: Semaphore to limit concurrent transcriptions. :ivar _concurrency: Semaphore to limit concurrent transcriptions.
:ivar _current_speech_reference: The reference of the current user utterance, for synchronising
experiment logs.
""" """
def __init__(self, audio_in_address: str): def __init__(self, audio_in_address: str):
@@ -39,6 +44,7 @@ class TranscriptionAgent(BaseAgent):
self.audio_in_socket: azmq.Socket | None = None self.audio_in_socket: azmq.Socket | None = None
self.speech_recognizer = None self.speech_recognizer = None
self._concurrency = None self._concurrency = None
self._current_speech_reference: str | None = None
async def setup(self): async def setup(self):
""" """
@@ -63,6 +69,10 @@ class TranscriptionAgent(BaseAgent):
self.logger.info("Finished setting up %s", self.name) self.logger.info("Finished setting up %s", self.name)
async def handle_message(self, msg: InternalMessage):
if msg.thread == "voice_activity":
self._current_speech_reference = msg.body
async def stop(self): async def stop(self):
""" """
Stop the agent and close sockets. Stop the agent and close sockets.
@@ -96,20 +106,21 @@ class TranscriptionAgent(BaseAgent):
async def _share_transcription(self, transcription: str): async def _share_transcription(self, transcription: str):
""" """
Share a transcription to the other agents that depend on it. Share a transcription to the other agents that depend on it, and to experiment logs.
Currently sends to: Currently sends to:
- :attr:`settings.agent_settings.text_belief_extractor_name` - :attr:`settings.agent_settings.text_belief_extractor_name`
- The UI via the experiment logger
:param transcription: The transcribed text. :param transcription: The transcribed text.
""" """
receiver_names = [ experiment_logger.chat(
settings.agent_settings.text_belief_extractor_name, transcription,
] extra={"role": "user", "reference": self._current_speech_reference, "partial": False},
)
for receiver_name in receiver_names:
message = InternalMessage( message = InternalMessage(
to=receiver_name, to=settings.agent_settings.text_belief_extractor_name,
sender=self.name, sender=self.name,
body=transcription, body=transcription,
) )
@@ -129,10 +140,9 @@ class TranscriptionAgent(BaseAgent):
audio = np.frombuffer(audio_data, dtype=np.float32) audio = np.frombuffer(audio_data, dtype=np.float32)
speech = await self._transcribe(audio) speech = await self._transcribe(audio)
if not speech: if not speech:
self.logger.info("Nothing transcribed.") self.logger.debug("Nothing transcribed.")
continue continue
self.logger.info("Transcribed speech: %s", speech)
await self._share_transcription(speech) await self._share_transcription(speech)
except Exception as e: except Exception as e:
self.logger.error(f"Error in transcription loop: {e}") self.logger.error(f"Error in transcription loop: {e}")

View File

@@ -1,4 +1,6 @@
import asyncio import asyncio
import logging
import uuid
import numpy as np import numpy as np
import torch import torch
@@ -12,6 +14,8 @@ from control_backend.schemas.internal_message import InternalMessage
from ...schemas.program_status import PROGRAM_STATUS, ProgramStatus from ...schemas.program_status import PROGRAM_STATUS, ProgramStatus
from .transcription_agent.transcription_agent import TranscriptionAgent from .transcription_agent.transcription_agent import TranscriptionAgent
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class SocketPoller[T]: class SocketPoller[T]:
""" """
@@ -252,6 +256,18 @@ class VADAgent(BaseAgent):
if prob > prob_threshold: if prob > prob_threshold:
if self.i_since_speech > non_speech_patience + begin_silence_length: if self.i_since_speech > non_speech_patience + begin_silence_length:
self.logger.debug("Speech started.") self.logger.debug("Speech started.")
reference = str(uuid.uuid4())
experiment_logger.chat(
"...",
extra={"role": "user", "reference": reference, "partial": True},
)
await self.send(
InternalMessage(
to=settings.agent_settings.transcription_name,
body=reference,
thread="voice_activity",
)
)
self.audio_buffer = np.append(self.audio_buffer, chunk) self.audio_buffer = np.append(self.audio_buffer, chunk)
self.i_since_speech = 0 self.i_since_speech = 0
continue continue

View File

@@ -1,4 +1,5 @@
import json import json
import logging
import zmq import zmq
from zmq.asyncio import Context from zmq.asyncio import Context
@@ -16,6 +17,8 @@ from control_backend.schemas.ri_message import (
SpeechCommand, SpeechCommand,
) )
experiment_logger = logging.getLogger(settings.logging_settings.experiment_logger_name)
class UserInterruptAgent(BaseAgent): class UserInterruptAgent(BaseAgent):
""" """
@@ -296,6 +299,7 @@ class UserInterruptAgent(BaseAgent):
:param text_to_say: The string that the robot has to say. :param text_to_say: The string that the robot has to say.
""" """
experiment_logger.chat(text_to_say, extra={"role": "assistant"})
cmd = SpeechCommand(data=text_to_say, is_priority=True) cmd = SpeechCommand(data=text_to_say, is_priority=True)
out_msg = InternalMessage( out_msg = InternalMessage(
to=settings.agent_settings.robot_speech_name, to=settings.agent_settings.robot_speech_name,