V1 of Structured Agent & Tool logging (#379)

This establishes the following pattern of logging:

- Named, constant keys present in the `extras` block can flag certain
logging messages as having a particular role or location within the
Agent processing pipeline.
- REPL output is logging-based, using knowledge of these special fields.
This avoids `print` statements and creates consistency between "what's
tracked / traced" and "what the REPL can show"

This permits the following follow-ups:

- The Fluent Logging handler in prod can ferry this structured data to
(like elastic)
- User-visible logs can filter out specific items like Actions take,
Thoughts thought, Tool inputs provided, etc.
- The AgentContext object can provide a logger which automatically adds
some of these special `extra` fields so the user doesn't need to be the
wiser

Author: eob

src/steamship/agents/logging.py

@@ -0,0 +1,38 @@
+class AgentLogging:
+    """These keys are for use in the `extra` field of agent logging operations. #noqa: RST203
+
+    For now, they are manually applied at the time of logging. In the future, the AgentContext may provide a logger
+    which fills some automatically.
+
+    For example:
+
+    logging.info("I should use tool MakeAPicture", extra={
+        AgentLogging.AGENT_NAME: self.name,
+        AgentLogging.IS_AGENT_MESSAGE: True,
+        AgentLogging.MESSAGE_TYPE: AgentLogging.THOUGHT
+    }) # noqa: RST203
+
+    This provides:
+
+    * Structured additions to Fluent/Elastic that help with internal debugging.
+    * Helpful output in development mode
+    * [Eventual] User-visible logs
+    * [Eventual] Visualiations about tool execution and ReAct reasoning
+
+    """
+
+    AGENT_NAME = "agent_name"
+    TOOL_NAME = "tool_name"
+    IS_MESSAGE = "is_message"
+
+    MESSAGE_TYPE = "agent_message_type"
+    THOUGHT = "thought"
+    OBSERVATION = "observation"
+    ACTION = "action"
+    MESSAGE = "message"
+
+    MESSAGE_AUTHOR = "message_author"
+    USER = "user"
+    AGENT = "agent"
+    TOOL = "tool"
+    SYSTEM = "system"

src/steamship/agents/service/agent_service.py

@@ -1,6 +1,7 @@
 import logging
 
 from steamship import SteamshipError, Task
+from steamship.agents.logging import AgentLogging
 from steamship.agents.schema import Action, Agent, FinishAction
 from steamship.agents.schema.context import AgentContext
 from steamship.invocable import PackageService
@@ -34,12 +35,28 @@ def run_action(self, action: Action, context: AgentContext):
     def run_agent(self, agent: Agent, context: AgentContext):
         action = agent.next_action(context=context)
         while not isinstance(action, FinishAction):
-            # TODO: logging?
-            logging.info(f"running action: {action}")
+            # TODO: Arrive at a solid design for the details of this structured log object
+            logging.info(
+                f"Running Tool {action.tool.name}",
+                extra={
+                    AgentLogging.TOOL_NAME: action.tool.name,
+                    AgentLogging.IS_MESSAGE: True,
+                    AgentLogging.MESSAGE_TYPE: AgentLogging.ACTION,
+                    AgentLogging.MESSAGE_AUTHOR: AgentLogging.AGENT,
+                },
+            )
             self.run_action(action=action, context=context)
             action = agent.next_action(context=context)
-            # TODO: logging?
-            logging.info(f"next action: {action}")
+            # TODO: Arrive at a solid design for the details of this structured log object
+            logging.info(
+                f"Next Tool: {action.tool.name}",
+                extra={
+                    AgentLogging.TOOL_NAME: action.tool.name,
+                    AgentLogging.IS_MESSAGE: False,
+                    AgentLogging.MESSAGE_TYPE: AgentLogging.ACTION,
+                    AgentLogging.MESSAGE_AUTHOR: AgentLogging.AGENT,
+                },
+            )
 
         context.completed_steps.append(action)
         for func in context.emit_funcs:

src/steamship/invocable/dev_logging_handler.py

@@ -0,0 +1,71 @@
+import logging
+from logging import StreamHandler
+from typing import cast
+
+from fluent.handler import FluentRecordFormatter
+
+from steamship.agents.logging import AgentLogging
+
+LOGGING_FORMAT = {
+    "level": "%(levelname)s",
+    "host": "%(hostname)s",
+    "where": "%(module)s.%(filename)s.%(funcName)s:%(lineno)s",
+    "type": "%(levelname)s",
+    "stack_trace": "%(exc_text)s",
+    "message_type": "%(message_type)s",
+    "component_name": "%(component_name)s",
+    AgentLogging.IS_MESSAGE: f"%({AgentLogging.IS_MESSAGE})s",  # b doesn't work. Unsure how to make a bool
+    AgentLogging.AGENT_NAME: f"%({AgentLogging.AGENT_NAME})s",
+    AgentLogging.MESSAGE_AUTHOR: f"%({AgentLogging.MESSAGE_AUTHOR})s",
+    AgentLogging.MESSAGE_TYPE: f"%({AgentLogging.MESSAGE_TYPE})s",
+    AgentLogging.TOOL_NAME: f"%({AgentLogging.TOOL_NAME})s",
+}
+
+
+class DevelopmentLoggingHandler(StreamHandler):
+    """A logging handler for developing Steamship Agents, Tools, Packages, and Plugins locally."""
+
+    log_level: any
+    log_level_with_message_type: any
+
+    def __init__(self, log_level: any = logging.WARN, log_level_for_messages: any = logging.INFO):
+        StreamHandler.__init__(self)
+        formatter = FluentRecordFormatter(LOGGING_FORMAT, fill_missing_fmt_key=True)
+        self.setFormatter(formatter)
+        self.log_level = log_level
+        self.log_level_for_messages = log_level_for_messages
+
+    def _emit_regular(self, message_dict: dict):
+        level = message_dict.get("level", None)
+        message = message_dict.get("message", None)
+        print(f"[{level}] {message}")
+
+    def _emit_message(self, message_dict: dict):
+        author = message_dict.get(AgentLogging.MESSAGE_AUTHOR, "Unknown")
+        message = message_dict.get("message", None)
+        message_type = message_dict.get(AgentLogging.MESSAGE_TYPE, AgentLogging.MESSAGE)
+
+        print(f"[{author} {message_type}] {message}")
+
+    def emit(self, record):
+        """Emit the record, printing it to console out.
+
+        We rely on TWO logging levels for the mechanics of this LoggingHandler:
+
+        - One for standard logging
+        - One for specific system Agent-related events, flagged with metadata
+
+        This is to permit INFO-level logging of key Agent/Tool actions without committing the user to see all
+        INFO-level logging globally.
+
+        A future implementation may use a cascade of loggers attached to the AgentContext to do this more cleanly.
+        """
+        message_dict = cast(dict, self.format(record))
+
+        # It will be returned as a string representation of a bool
+        is_message = message_dict.get(AgentLogging.IS_MESSAGE, None) == "True"
+
+        if record.levelno >= self.log_level and not is_message:
+            return self._emit_regular(message_dict)
+        elif record.levelno >= self.log_level_for_messages and is_message:
+            return self._emit_message(message_dict)

src/steamship/utils/repl.py

@@ -6,16 +6,26 @@
 from typing import Any, Dict, List, Optional, Type, cast
 
 from steamship import Block, Steamship, Task
+from steamship.agents.logging import AgentLogging
 from steamship.agents.schema import AgentContext, Tool
 from steamship.agents.service.agent_service import AgentService
 from steamship.data.workspace import SignedUrl, Workspace
+from steamship.invocable.dev_logging_handler import DevelopmentLoggingHandler
 from steamship.utils.signed_urls import upload_to_signed_url
 
 
 class SteamshipREPL(ABC):
     """Base class for building REPLs that facilitate running Steamship code in the IDE."""
 
     client: Steamship
+    dev_logging_handler: DevelopmentLoggingHandler
+
+    def __init__(self, log_level=None):
+        logger = logging.getLogger()
+        logger.handlers.clear()
+        logger.setLevel(log_level or logging.DEBUG)
+        dev_logging_handler = DevelopmentLoggingHandler()
+        logger.addHandler(dev_logging_handler)
 
     def _make_public_url(self, block):
         filepath = str(uuid.uuid4())
@@ -47,18 +57,29 @@ def _make_public_url(self, block):
 
     def print_blocks(self, blocks: List[Block], metadata: Dict[str, Any]):
         """Print a list of blocks to console."""
+        output = None
+
         for block in blocks:
             if isinstance(block, dict):
                 block = Block.parse_obj(block)
             if block.is_text():
-                print(block.text)
+                output = block.text
             elif block.url:
-                print(block.url)
+                output = block.url
             elif block.content_url:
-                print(block.content_url)
+                output = block.content_url
             else:
                 url = self._make_public_url(block)
-                print(url)
+                output = url
+
+        if output:
+            logging.info(
+                f"{output}",
+                extra={
+                    AgentLogging.IS_MESSAGE: True,
+                    AgentLogging.MESSAGE_AUTHOR: AgentLogging.AGENT,
+                },
+            )
 
     @contextlib.contextmanager
     def temporary_workspace(self) -> Steamship:
@@ -145,8 +166,9 @@ def colored(text: str, color: str):
 
         while True:
             input_text = input(colored(text="Input: ", color="blue"))  # noqa: F821
-            fn = getattr(agent_service, self.method)
-            print(colored(text=f"{fn(input_text)}", color="green", force_color=True))
+            responder = getattr(agent_service, self.method)
+            response = responder(input_text)
+            print(colored(text=f"{response}", color="green", force_color=True))
 
     def run(self):
         with self.temporary_workspace() as client: