Logger INFO not show when function call from langchain agent executor.

[Lin-jun-xiang]

Checked other resources

• I added a very descriptive title to this question.
• I searched the LangChain documentation with the integrated search.
• I used the GitHub search to find a similar question and didn't find it.

Commit to Help

• I commit to help with one of those options 👆

Example Code

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

conn = Go2Connection(
    robot_ip=ROBOT_IP,
    robot_num="0",
    token="",
    on_validated=lambda _: logger.info("Robot validated"),
    on_message=lambda msg, _, __: logger.info(f"Message received: {msg}")
)

@tool
async def go2_scrape():
    """Greeting the New Year - Control GO2(machine)"""
    conn.data_channel.send(
        gen_command(ROBOT_CMD['Scrape'])
    )
    logger.info(f"Scrape command sent")

Description

When I try to control the robot dog (go2) using WebRTC, each time conn.data_channel.send is called, logger.info logs "received message" via on_message if I don't use the agent. However, when I introduce the agent concept, the agent_executor(astream_event) calling the function triggers conn.data_channel.send, and the logger does not display any messages.

Here is the original code of Go2Connection: Go2Connection original code.

import base64
import hashlib
import json
import logging
import time

import aiohttp
from aiortc import RTCPeerConnection, RTCSessionDescription
from aiortc.contrib.media import MediaBlackhole

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)


class Go2Connection():
    def __init__(self, robot_ip, robot_num, token="", on_validated=None, on_message=None, on_open=None):
        self.pc = RTCPeerConnection()
        self.robot_ip = robot_ip
        self.robot_num = str(robot_num)
        self.token = token
        self.robot_validation = "PENDING"
        self.on_validated = on_validated
        self.on_message = on_message
        self.on_open = on_open
        
        self.audio_track = MediaBlackhole()
        self.video_track = MediaBlackhole()
        
        self.data_channel = self.pc.createDataChannel("data", id=0)
        self.data_channel.on("open", self.on_data_channel_open)
        self.data_channel.on("message", self.on_data_channel_message)
        
        self.pc.on("track", self.on_track)
        self.pc.on("connectionstatechange", self.on_connection_state_change)

    def on_connection_state_change(self):
        logger.info(f"Connection state is {self.pc.connectionState}")

    def on_track(self, track):
        logger.info(f"Receiving {track.kind}")

    async def generate_offer(self):
        await self.audio_track.start()
        await self.video_track.start()
        offer = await self.pc.createOffer()
        await self.pc.setLocalDescription(offer)
        return offer.sdp
    
    async def set_answer(self, sdp):
        answer = RTCSessionDescription(sdp, type="answer")
        await self.pc.setRemoteDescription(answer)
    
    def on_data_channel_open(self):
        logger.info("Data channel is open")
        if self.on_open:
            self.on_open()
    
    def on_data_channel_message(self, msg):
        logger.info(f"Received message: {msg}")

        if self.data_channel.readyState != "open":
            self.data_channel._setReadyState("open")

        try:
            if isinstance(msg, str):
                msgobj = json.loads(msg)
                if msgobj.get("type") == "validation":
                    self.validate_robot_conn(msgobj)
            if self.on_message:
                self.on_message(msg, msgobj, self.robot_num)
        except json.JSONDecodeError:
            pass
    
    async def connect(self):
        offer = await self.generate_offer()
        url = f"http://{self.robot_ip}:8081/offer"
        headers = {"Content-Type": "application/json"}
        data = {
            "sdp": offer,
            "id": "STA_localNetwork",
            "type": "offer",
            "token": "",
        }

        connected = False
        while not connected:
            async with aiohttp.ClientSession() as session:
                async with session.post(url, json=data, headers=headers) as resp:
                    if resp.status == 200:
                        answer_data = await resp.json()
                        answer_sdp = answer_data.get("sdp")
                        await self.set_answer(answer_sdp)
                        connected = True
                    else:
                        logger.info(f"Failed to get answer from server: Reason: {resp}")
                        logger.info("Try to reconnect...")
                        time.sleep(1)

    def validate_robot_conn(self, message):
        if message.get("data") == "Validation Ok.":
            self.robot_validation = "SUCCESS"
            if self.on_validated:
                self.on_validated(self.robot_num)
        else:
            self.publish(
                "",
                self.encrypt_key(message.get("data")),
                "validation",
            )

    def publish(self, topic, data, msg_type):
        if self.data_channel.readyState != "open":
            logger.info(f"Data channel is not open. State is {self.data_channel.readyState}")
            return
        
        payload = {
            "type": msg_type,
            "topic": topic,
            "data": data,
        }

        payload_dumped = json.dumps(payload)
        logger.info(f"-> Sending message {payload_dumped}")
        self.data_channel.send(payload_dumped)

    @staticmethod
    def hex_to_base64(hex_str):
        bytes_array = bytes.fromhex(hex_str)
        return base64.b64encode(bytes_array).decode("utf-8")

    @staticmethod
    def encrypt_key(key):
        prefixed_key = f"UnitreeGo2_{key}"
        encrypted = Go2Connection.encrypt_by_md5(prefixed_key)
        return Go2Connection.hex_to_base64(encrypted)

    @staticmethod
    def encrypt_by_md5(input_str):
        hash_obj = hashlib.md5()
        hash_obj.update(input_str.encode("utf-8"))
        return hash_obj.hexdigest()

System Info

System Information

OS: Windows
OS Version: 10.0.19045
Python Version: 3.11.8 (tags/v3.11.8:db85d51, Feb 6 2024, 22:03:32) [MSC v.1937 64 bit (AMD64)]

Package Information

langchain_core: 0.2.10
langchain: 0.2.6
langchain_community: 0.2.1
langsmith: 0.1.82
langchain_text_splitters: 0.2.0
langchainhub: 0.1.20

Packages not installed (Not Necessarily a Problem)

The following packages were not found:

langgraph
langserve

[dosubot[bot]]

logger.info messages are not displayed when a function is called from a LangChain agent executor because the default logging configuration does not include all events. To see all events, including logger.info messages, you need to enable Debug Mode by setting the global debug flag.

from langchain.globals import set_debug

set_debug(True)
agent_executor = AgentExecutor(agent=agent, tools=tools)
agent_executor.invoke(
    {"input": "Who directed the 2023 film Oppenheimer and what is their age in days?"}
)

This will cause all LangChain components with callback support to print the inputs they receive and outputs they generate, ensuring that logger.info messages are displayed. Additionally, ensure that the logging level is set to INFO or lower in your logging configuration:

import logging

logging.basicConfig(level=logging.INFO)

This ensures that logger.info messages are not filtered out by the logging configuration ^[1][2].

To continue talking to Dosu, mention @dosu.

[Lin-jun-xiang]

I have try to use set_debug(True), however the logger from on_message=lambda msg, _, __: logger.info(f"Message received: {msg}") still not show.

[dosubot[bot]]

To ensure that logger.info messages are displayed from the on_message callback, you need to make sure that the logging configuration is correctly set up and that the LangChain agent does not interfere with the logging mechanism. Here are a few steps to troubleshoot and resolve the issue:

1. Ensure Logging Configuration: Make sure the logging level is set to INFO and that the logger is properly configured to output to the console.

2. Use LoggingCallbackHandler: Integrate the LoggingCallbackHandler provided by LangChain to handle logging within the LangChain framework.

3. Check Asynchronous Execution: If the function is asynchronous, ensure that the logging is correctly handled in an asynchronous context.

Here is an example of how to configure the logging and use the LoggingCallbackHandler:

import logging
from langchain.callbacks.tracers.logging import LoggingCallbackHandler
from langchain.globals import set_debug

# Set the logging level to INFO
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger('langchain')
logger.setLevel(logging.INFO)

# Optionally, add a handler to output logs to the console
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
console_handler.setFormatter(formatter)
logger.addHandler(console_handler)

# Use the LoggingCallbackHandler
logging_callback_handler = LoggingCallbackHandler(logger=logger, log_level=logging.INFO)

# Set debug mode
set_debug(True)

# Example of using the agent executor with the logging callback handler
agent_executor = AgentExecutor(agent=agent, tools=tools, callbacks=[logging_callback_handler])
agent_executor.invoke(
    {"input": "Who directed the 2023 film Oppenheimer and what is their age in days?"}
)

# Ensure the Go2Connection is properly configured
conn = Go2Connection(
    robot_ip=ROBOT_IP,
    robot_num="0",
    token="",
    on_validated=lambda _: logger.info("Robot validated"),
    on_message=lambda msg, _, __: logger.info(f"Message received: {msg}")
)

@tool
async def go2_scrape():
    """Greeting the New Year - Control GO2(machine)"""
    conn.data_channel.send(
        gen_command(ROBOT_CMD['Scrape'])
    )
    logger.info(f"Scrape command sent")

By following these steps, you should be able to see the logger.info messages from the on_message callback when the function is called from the LangChain agent executor ^[1][2].

To continue talking to Dosu, mention @dosu.

[Lin-jun-xiang]

@dosu
The problem still exist, I have edited the question in first time.

[dosubot[bot]]

To ensure that logger.info messages from the on_message callback are displayed when the function is called from the LangChain agent executor, you need to set up a LoggingCallbackHandler with the appropriate logger and log level. Here is an example of how you can do this:

import logging
from langchain.callbacks.tracers.logging import LoggingCallbackHandler

# Set up the logger
logger = logging.getLogger('my_logger')
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

# Create the LoggingCallbackHandler
logging_callback_handler = LoggingCallbackHandler(logger=logger, log_level=logging.INFO)

# Assuming you have an agent executor, you can add the callback handler to it
agent_executor.add_callback_handler(logging_callback_handler)

# Now, when the on_message callback is called, it will log the info messages

Additionally, ensure that the Go2Connection class and the on_message callback are properly configured to use the logger:

conn = Go2Connection(
    robot_ip=ROBOT_IP,
    robot_num="0",
    token="",
    on_validated=lambda _: logger.info("Robot validated"),
    on_message=lambda msg, _, __: logger.info(f"Message received: {msg}")
)

@tool
async def go2_scrape():
    """Greeting the New Year - Control GO2(machine)"""
    conn.data_channel.send(
        gen_command(ROBOT_CMD['Scrape'])
    )
    logger.info(f"Scrape command sent")

By setting up the LoggingCallbackHandler and ensuring the logger is properly configured, you should be able to see the logger.info messages from the on_message callback when the function is called from the LangChain agent executor ^[1][2][3].

To continue talking to Dosu, mention @dosu.