OpenAI API sporadically rejects tool calls #348
Description
Version: main, HEAD: b000f44
Mostly likely hallucination related given that it occurs only rarely (worked fine for 36 questions and crashed on the 37th). The exact cause is to be figured out
(2025-11-26 09:43:51,956) [__main__] INFO: ====================================
(2025-11-26 09:43:51,956) [__main__] INFO: Answering question: 36
(2025-11-26 09:43:51,956) [__main__] INFO: Question: Summarize the objective of CMSTRANSF-1243.
(2025-11-26 09:43:51,956) [__main__] INFO: Reference Answer: CMSTRANSF-1243 — Re-evaluate transfer failure alerting (Action item)
Problem:
• Alerts lag operations; some not triggered
Risk:
• Lower thresholds → alert fatigue
Proposal:
• Use Rucio data and percentage-based thresholds
Link:
• Related to failures in CMSTRANSF-1242
(2025-11-26 09:43:51,956) [__main__] INFO: Reference Sources: ['CMSTRANSF-1243']
(2025-11-26 09:43:51,959) [httpx] DEBUG: load_ssl_context verify=True cert=None trust_env=True http2=False
(2025-11-26 09:43:51,960) [httpx] DEBUG: load_verify_locations cafile='/usr/local/lib/python3.10/site-packages/certifi/cacert.pem'
(2025-11-26 09:43:51,973) [chromadb.config] DEBUG: Starting component System
(2025-11-26 09:43:51,973) [chromadb.config] DEBUG: Starting component Posthog
(2025-11-26 09:43:51,973) [chromadb.config] DEBUG: Starting component OpenTelemetryClient
(2025-11-26 09:43:51,973) [chromadb.config] DEBUG: Starting component FastAPI
(2025-11-26 09:43:51,976) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/auth/identity "HTTP/1.1 200 OK"
(2025-11-26 09:43:51,978) [httpx] DEBUG: load_ssl_context verify=True cert=None trust_env=True http2=False
(2025-11-26 09:43:51,980) [httpx] DEBUG: load_verify_locations cafile='/usr/local/lib/python3.10/site-packages/certifi/cacert.pem'
(2025-11-26 09:43:51,997) [chromadb.config] DEBUG: Starting component System
(2025-11-26 09:43:51,997) [chromadb.config] DEBUG: Starting component Posthog
(2025-11-26 09:43:51,997) [chromadb.config] DEBUG: Starting component OpenTelemetryClient
(2025-11-26 09:43:51,997) [chromadb.config] DEBUG: Starting component FastAPI
(2025-11-26 09:43:52,000) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant "HTTP/1.1 200 OK"
(2025-11-26 09:43:52,001) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database "HTTP/1.1 200 OK"
(2025-11-26 09:43:52,005) [httpx] INFO: HTTP Request: POST http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections "HTTP/1.1 200 OK"
(2025-11-26 09:43:52,007) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/default_collection_with_HuggingFaceEmbeddings "HTTP/1.1 200 OK"
(2025-11-26 09:43:52,014) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/4f4ccb1e-0f3d-4b2a-a538-91a3518d592e/count "HTTP/1.1 200 OK"
(2025-11-26 09:43:52,014) [src.a2rchi.utils.vectorstore_connector] DEBUG: N entries: 11857
(2025-11-26 09:43:52,014) [src.a2rchi.utils.vectorstore_connector] DEBUG: Updated vectorstore connection
(2025-11-26 09:43:52,014) [src.a2rchi.pipelines.agents.base] DEBUG: Invoking CMSCompOpsAgent
(2025-11-26 09:43:53,079) [httpx] INFO: HTTP Request: POST http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/4f4ccb1e-0f3d-4b2a-a538-91a3518d592e/get "HTTP/1.1 200 OK"
(2025-11-26 09:43:53,392) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: Retrieved 11857 documents for BM25 corpus
(2025-11-26 09:43:53,397) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: Loaded 11857 documents for BM25 corpus from vectorstore.
(2025-11-26 09:43:54,673) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: BM25 retriever created with 11857 documents
(2025-11-26 09:43:54,686) [src.data_manager.collectors.utils.index_utils] DEBUG: Refreshing catalog indices from /root/data
(2025-11-26 09:43:55,265) [src.a2rchi.pipelines.agents.base] DEBUG: Refreshing agent CMSCompOpsAgent with 4 tools
(2025-11-26 09:43:55,265) [src.a2rchi.pipelines.agents.base] DEBUG: Creating agent CMSCompOpsAgent with 4 tools
(2025-11-26 09:43:55,271) [src.a2rchi.pipelines.agents.base] DEBUG: Agent refreshed, invoking now
(2025-11-26 09:43:56,241) [httpx] INFO: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 200 OK"
(2025-11-26 09:43:58,254) [src.a2rchi.pipelines.agents.cms_comp_ops_agent] DEBUG: Recording 1 documents from stage 'search_metadata_index: CMSTRANSF-1243' via record_documents
(2025-11-26 09:44:06,520) [httpx] INFO: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,526) [src.a2rchi.pipelines.agents.base] DEBUG: Agent invocation completed
(2025-11-26 09:44:06,526) [__main__] INFO: Finished answering question: 36 (14.57s)
(2025-11-26 09:44:06,527) [__main__] WARNING: Unexpected message type: <class 'langchain_core.messages.tool.ToolMessage'>
(2025-11-26 09:44:06,528) [__main__] DEBUG: Checking for reference source 'CMSTRANSF-1243' in field 'ticket_id'
(2025-11-26 09:44:06,528) [__main__] INFO: Returned source 'ticket_id': ['CMSTRANSF-1243']
(2025-11-26 09:44:06,528) [__main__] DEBUG: Checking reference 'CMSTRANSF-1243' against document metadata field 'ticket_id': ['CMSTRANSF-1243']
(2025-11-26 09:44:06,528) [__main__] DEBUG: Matched reference source 'CMSTRANSF-1243' in document metadata.
(2025-11-26 09:44:06,528) [__main__] INFO: Source matching result: [True]
(2025-11-26 09:44:06,528) [__main__] INFO: Current relative accuracy: 0.8055555555555556
(2025-11-26 09:44:06,528) [__main__] INFO: Current strict accuracy: 0.7222222222222222
(2025-11-26 09:44:06,529) [__main__] DEBUG: Sources returned: [{'source': '/root/data/tickets/jira_CMSTRANSF-1243.txt', 'created_at': '2025-10-17T09:18:32.000+0200', 'display_name': 'https://its.cern.ch/jira/browse/CMSTRANSF-1243', 'project': 'CMSTRANSF', 'source_type': 'jira', 'ticket_id': 'CMSTRANSF-1243', 'url': 'https://its.cern.ch/jira/browse/CMSTRANSF-1243'}]
(2025-11-26 09:44:06,529) [__main__] INFO: ====================================
(2025-11-26 09:44:06,529) [__main__] INFO:
(2025-11-26 09:44:06,529) [__main__] INFO:
(2025-11-26 09:44:06,529) [__main__] INFO: ====================================
(2025-11-26 09:44:06,529) [__main__] INFO: Answering question: 37
(2025-11-26 09:44:06,529) [__main__] INFO: Question: Briefly describe the change in CMSTRANSF-1039.
(2025-11-26 09:44:06,529) [__main__] INFO: Reference Answer: CMSTRANSF-1039 — Monitor transfer volume without FTS logs (Implemented)
Why:
• FTS marks buffer OK even if tape write retries; misleading
Action:
• Added Grafana plots using Rucio events (volume, throughput)
Where:
• cms-fts-metrics dashboard (extra tab)
(2025-11-26 09:44:06,529) [__main__] INFO: Reference Sources: ['CMSTRANSF-1039']
(2025-11-26 09:44:06,532) [httpx] DEBUG: load_ssl_context verify=True cert=None trust_env=True http2=False
(2025-11-26 09:44:06,534) [httpx] DEBUG: load_verify_locations cafile='/usr/local/lib/python3.10/site-packages/certifi/cacert.pem'
(2025-11-26 09:44:06,546) [chromadb.config] DEBUG: Starting component System
(2025-11-26 09:44:06,546) [chromadb.config] DEBUG: Starting component Posthog
(2025-11-26 09:44:06,546) [chromadb.config] DEBUG: Starting component OpenTelemetryClient
(2025-11-26 09:44:06,546) [chromadb.config] DEBUG: Starting component FastAPI
(2025-11-26 09:44:06,549) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/auth/identity "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,551) [httpx] DEBUG: load_ssl_context verify=True cert=None trust_env=True http2=False
(2025-11-26 09:44:06,553) [httpx] DEBUG: load_verify_locations cafile='/usr/local/lib/python3.10/site-packages/certifi/cacert.pem'
(2025-11-26 09:44:06,570) [chromadb.config] DEBUG: Starting component System
(2025-11-26 09:44:06,570) [chromadb.config] DEBUG: Starting component Posthog
(2025-11-26 09:44:06,570) [chromadb.config] DEBUG: Starting component OpenTelemetryClient
(2025-11-26 09:44:06,570) [chromadb.config] DEBUG: Starting component FastAPI
(2025-11-26 09:44:06,573) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,574) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,582) [httpx] INFO: HTTP Request: POST http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,586) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/default_collection_with_HuggingFaceEmbeddings "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,595) [httpx] INFO: HTTP Request: GET http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/4f4ccb1e-0f3d-4b2a-a538-91a3518d592e/count "HTTP/1.1 200 OK"
(2025-11-26 09:44:06,596) [src.a2rchi.utils.vectorstore_connector] DEBUG: N entries: 11857
(2025-11-26 09:44:06,596) [src.a2rchi.utils.vectorstore_connector] DEBUG: Updated vectorstore connection
(2025-11-26 09:44:06,596) [src.a2rchi.pipelines.agents.base] DEBUG: Invoking CMSCompOpsAgent
(2025-11-26 09:44:07,586) [httpx] INFO: HTTP Request: POST http://localhost:8005/api/v2/tenants/default_tenant/databases/default_database/collections/4f4ccb1e-0f3d-4b2a-a538-91a3518d592e/get "HTTP/1.1 200 OK"
(2025-11-26 09:44:07,883) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: Retrieved 11857 documents for BM25 corpus
(2025-11-26 09:44:07,886) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: Loaded 11857 documents for BM25 corpus from vectorstore.
(2025-11-26 09:44:08,649) [src.data_manager.vectorstore.retrievers.bm25_retriever] DEBUG: BM25 retriever created with 11857 documents
(2025-11-26 09:44:08,662) [src.data_manager.collectors.utils.index_utils] DEBUG: Refreshing catalog indices from /root/data
(2025-11-26 09:44:09,583) [src.a2rchi.pipelines.agents.base] DEBUG: Refreshing agent CMSCompOpsAgent with 4 tools
(2025-11-26 09:44:09,583) [src.a2rchi.pipelines.agents.base] DEBUG: Creating agent CMSCompOpsAgent with 4 tools
(2025-11-26 09:44:09,588) [src.a2rchi.pipelines.agents.base] DEBUG: Agent refreshed, invoking now
(2025-11-26 09:44:10,644) [httpx] INFO: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 200 OK"
(2025-11-26 09:44:10,806) [httpx] INFO: HTTP Request: POST https://api.openai.com/v1/chat/completions "HTTP/1.1 400 Bad Request"
Traceback (most recent call last):
File "/root/A2rchi/src/bin/service_benchmark.py", line 515, in <module>
benchmarker.run()
File "/root/A2rchi/src/bin/service_benchmark.py", line 412, in run
result = self.chain(history=formatted_question)
File "/usr/local/lib/python3.10/site-packages/src/a2rchi/a2rchi.py", line 110, in __call__
return self.invoke(*args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/src/a2rchi/a2rchi.py", line 86, in invoke
result = self.pipeline.invoke(*args, **call_kwargs)
File "/usr/local/lib/python3.10/site-packages/src/a2rchi/pipelines/agents/base.py", line 89, in invoke
answer_output = self.agent.invoke(agent_inputs, {"recursion_limit": 50})
File "/usr/local/lib/python3.10/site-packages/langgraph/pregel/main.py", line 3094, in invoke
for chunk in self.stream(
File "/usr/local/lib/python3.10/site-packages/langgraph/pregel/main.py", line 2679, in stream
for _ in runner.tick(
File "/usr/local/lib/python3.10/site-packages/langgraph/pregel/_runner.py", line 167, in tick
run_with_retry(
File "/usr/local/lib/python3.10/site-packages/langgraph/pregel/_retry.py", line 42, in run_with_retry
return task.proc.invoke(task.input, config)
File "/usr/local/lib/python3.10/site-packages/langgraph/_internal/_runnable.py", line 656, in invoke
input = context.run(step.invoke, input, config, **kwargs)
File "/usr/local/lib/python3.10/site-packages/langgraph/_internal/_runnable.py", line 400, in invoke
ret = self.func(*args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/langchain/agents/factory.py", line 1034, in model_node
response = _execute_model_sync(request)
File "/usr/local/lib/python3.10/site-packages/langchain/agents/factory.py", line 1007, in _execute_model_sync
output = model_.invoke(messages)
File "/usr/local/lib/python3.10/site-packages/langchain_core/runnables/base.py", line 5492, in invoke
return self.bound.invoke(
File "/usr/local/lib/python3.10/site-packages/langchain_core/language_models/chat_models.py", line 379, in invoke
self.generate_prompt(
File "/usr/local/lib/python3.10/site-packages/langchain_core/language_models/chat_models.py", line 1088, in generate_prompt
return self.generate(prompt_messages, stop=stop, callbacks=callbacks, **kwargs)
File "/usr/local/lib/python3.10/site-packages/langchain_core/language_models/chat_models.py", line 903, in generate
self._generate_with_cache(
File "/usr/local/lib/python3.10/site-packages/langchain_core/language_models/chat_models.py", line 1192, in _generate_with_cache
result = self._generate(
File "/usr/local/lib/python3.10/site-packages/langchain_openai/chat_models/base.py", line 1299, in _generate
raise e
File "/usr/local/lib/python3.10/site-packages/langchain_openai/chat_models/base.py", line 1294, in _generate
raw_response = self.client.with_raw_response.create(**payload)
File "/usr/local/lib/python3.10/site-packages/openai/_legacy_response.py", line 364, in wrapped
return cast(LegacyAPIResponse[R], func(*args, **kwargs))
File "/usr/local/lib/python3.10/site-packages/openai/_utils/_utils.py", line 286, in wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/openai/resources/chat/completions/completions.py", line 1147, in create
return self._post(
File "/usr/local/lib/python3.10/site-packages/openai/_base_client.py", line 1259, in post
return cast(ResponseT, self.request(cast_to, opts, stream=stream, stream_cls=stream_cls))
File "/usr/local/lib/python3.10/site-packages/openai/_base_client.py", line 1047, in request
raise self._make_status_error_from_response(err.response) from None
openai.BadRequestError: Error code: 400 - {'error': {'message': "Invalid 'messages[2].tool_calls[0].function.name': string does not match pattern. Expected a string that matches the pattern '^[a-zA-Z0-9_-]+$'.", 'type': 'invalid_request_error', 'param': 'messages[2].tool_calls[0].function.name', 'code': 'invalid_value'}}