[Bug] Streaming output error of tool calling has still not been resolved.

[Sala8888]

I used the hermes_tool_parser.py as tool-parser-plugin and registered the parser as hermes_patched, but still have the same problem.

Already referred to #9874 #10395 #10398

Traceback (most recent call last):
  File "/app/hermes_tool_parser.py", line 228, in extract_tool_calls_streaming
    function_name: Union[str, None] = current_tool_call.get("name")
                                      ^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
Error trying to handle streaming tool call.
Traceback (most recent call last):
  File "/app/hermes_tool_parser.py", line 292, in extract_tool_calls_streaming
    args_delta_start_loc = cur_arguments_json.index(delta_text) \
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: substring not found

Here is how I start vllm service with the latest package:

python3 -m vllm.entrypoints.openai.api_server \
--model /app/Qwen2.5-72B-Instruct-AWQ \
--port 7415 \
--tensor-parallel-size 2 \
--gpu-memory-utilization 0.95 \
--max-model-len 64000 \
--enforce-eager \
--disable_custom_all_reduce \
--enable-auto-tool-choice \
--tool-parser-plugin /app/hermes_tool_parser.py \
--tool-call-parser hermes_patched  \
--chat-template /app/qwen.jinja

I also tried using Docker image v0.6.3.post1 v0.6.4 v0.6.4.post1

Originally posted by @Sala8888 in #10398 (comment)

[sycamore792]

I got the same problem,

ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Error trying to handle streaming tool call.
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Traceback (most recent call last):
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 227, in extract_tool_calls_streaming
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] function_name: Union[str, None] = current_tool_call.get("name")
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] AttributeError: 'NoneType' object has no attribute 'get'
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Error trying to handle streaming tool call.
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Traceback (most recent call last):
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 291, in extract_tool_calls_streaming
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] args_delta_start_loc = cur_arguments_json.index(delta_text)
ERROR 11-23 01:34:01 hermes_tool_parser.py:338] ValueError: substring not found
ERROR 11-23 01:34:02 hermes_tool_parser.py:338] Error trying to handle streaming tool call.
ERROR 11-23 01:34:02 hermes_tool_parser.py:338] Traceback (most recent call last):
ERROR 11-23 01:34:02 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 291, in extract_tool_calls_streaming
ERROR 11-23 01:34:02 hermes_tool_parser.py:338] args_delta_start_loc = cur_arguments_json.index(delta_text)
ERROR 11-23 01:34:02 hermes_tool_parser.py:338] ValueError: substring not found

besides, when i print the tool_calls function.arguments in strem mode like:

for chunk in create:
    try:
        print(chunk.choices[0].delta.tool_calls[0].function.arguments,end="")
    except Exception as e:
        pass
        

the output like :

None{"args":"entity": ""\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8, "func": ""get_company_funding{"args": {"entity": "\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8"}, "func": "get_company_funding"}

It is very unfriendly for me to parse json

[DarkLight1337]

cc @K-Mistele

[Sala8888]

Supplementary note.

Before using a new parser, LLM displayed the tool calling arguments in the content of response instead of tool_call.
At the same time, the vllm server also reported the same error.
Here are some examples of response:

現在我將查詢 DB 中的所有 controller 信息。
<tool_call>
{"name": "text_to_sql", "arguments": {"retrieve_steps": "查全部的controller", "columns": "*", "analysis_method": "summary the data and get max", "db_name": "21", "plot": false, "return_sql": false}}}
</tool_call>

請稍等，我會盡快完成分析並提供給您。

<tool_response>
{"name": "voice_to_text", "arguments": {"AudioPath": "["/path/example.mp3"]", "KeywordsPath": "None", "language": "zh"}
</tool_response>

When I modify the code using the above method, LLM directly response the error.

Hope this problem can be solved as soon as possible, thank you!

[Sala8888]

@cedonley @joennlae
Thank you for your fix, but the problem is still not solved.

I have read [Bugfix] Multiple fixes to tool streaming when using auto tool choice. and [Bugfix] fix race condition that leads to wrong order of token returned and installed the latest version of vllm using the instructions from here:

pip install https://vllm-wheels.s3.us-west-2.amazonaws.com/nightly/vllm-1.0.0.dev-cp38-abi3-manylinux1_x86_64.whl

The version is 0.6.4.post2.dev202+ge25810ae

But vllm server still has the same error:

INFO 12-02 12:13:00 engine.py:267] Added request chatcmpl-906ae28088d14caca3e3a355ac0a3036.
INFO 12-02 12:13:00 metrics.py:460] Avg prompt throughput: 171.5 tokens/s, Avg generation throughput: 4.2 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.8%, CPU KV cache usage: 0.0%.
ERROR 12-02 12:13:02 hermes_tool_parser.py:337] Error trying to handle streaming tool call.
ERROR 12-02 12:13:02 hermes_tool_parser.py:337] Traceback (most recent call last):
ERROR 12-02 12:13:02 hermes_tool_parser.py:337]   File "/opt/conda/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 228, in extract_tool_calls_streaming
ERROR 12-02 12:13:02 hermes_tool_parser.py:337]     function_name: Union[str, None] = current_tool_call.get("name")
ERROR 12-02 12:13:02 hermes_tool_parser.py:337] AttributeError: 'NoneType' object has no attribute 'get'
INFO 12-02 12:13:05 metrics.py:460] Avg prompt throughput: 296.4 tokens/s, Avg generation throughput: 15.3 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.8%, CPU KV cache usage: 0.0%.
INFO 12-02 12:13:20 metrics.py:460] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 8.4 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.

Did I do something wrong? Or is this bug not resolved yet?

[cedonley]

The PR is not yet merged, but based on the error in the logs, I believe it may be resolved once the PR is merged, as the error raised is one of several that I resolved in my commits.

[Sala8888]

Thanks for your reply, I will wait for the PR to be merged!

[K-Mistele]

I got the same problem,

ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Error trying to handle streaming tool call. ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Traceback (most recent call last): ERROR 11-23 01:34:01 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 227, in extract_tool_calls_streaming ERROR 11-23 01:34:01 hermes_tool_parser.py:338] function_name: Union[str, None] = current_tool_call.get("name") ERROR 11-23 01:34:01 hermes_tool_parser.py:338] AttributeError: 'NoneType' object has no attribute 'get' ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Error trying to handle streaming tool call. ERROR 11-23 01:34:01 hermes_tool_parser.py:338] Traceback (most recent call last): ERROR 11-23 01:34:01 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 291, in extract_tool_calls_streaming ERROR 11-23 01:34:01 hermes_tool_parser.py:338] args_delta_start_loc = cur_arguments_json.index(delta_text) ERROR 11-23 01:34:01 hermes_tool_parser.py:338] ValueError: substring not found ERROR 11-23 01:34:02 hermes_tool_parser.py:338] Error trying to handle streaming tool call. ERROR 11-23 01:34:02 hermes_tool_parser.py:338] Traceback (most recent call last): ERROR 11-23 01:34:02 hermes_tool_parser.py:338] File "/home/sycamore/.conda/envs/llm_env/lib/python3.10/site-packages/vllm/entrypoints/openai/tool_parsers/hermes_tool_parser.py", line 291, in extract_tool_calls_streaming ERROR 11-23 01:34:02 hermes_tool_parser.py:338] args_delta_start_loc = cur_arguments_json.index(delta_text) ERROR 11-23 01:34:02 hermes_tool_parser.py:338] ValueError: substring not found

besides, when i print the tool_calls function.arguments in strem mode like:

for chunk in create:
    try:
        print(chunk.choices[0].delta.tool_calls[0].function.arguments,end="")
    except Exception as e:
        pass
        

the output like :

None{"args":"entity": ""\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8, "func": ""get_company_funding{"args": {"entity": "\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8"}, "func": "get_company_funding"}

It is very unfriendly for me to parse json

This:

None{"args":"entity": ""\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8, "func": ""get_company_funding{"args": {"entity": "\u5e7f\u4e1c\u641c\u4e00\u641c\u79d1\u6280\u6709\u9650\u516c\u53f8"}, "func": "get_company_funding"}

Doesn't look like the model is trying to generate a valid tool call; the structure is off. Possibly a chat template issue, or a precision loss with the AWQ Quant?

Can you share your chat template and the tools you're passing to the model? Hard to debug without these.

[cedonley]

Hi @K-Mistele They are not printing the full tool call, only the arguments. The issues are (outlined in my PR mentioned earlier) is:

1. We're extensively using json.loads/dumps() calls, which explains why the model returns UTF-8 without the tool parsing, but is encoding non-ascii characters within the tool call. This isn't a showstopper except that we're mixing and matching ensure_ascii=False w/ the default (True) in various parsers, which breaks non-ascii arguments at times given that the "diffs" won't match (note the extra quotes and the missing {'s that invalidate this JSON...this is from the diffs getting misaligned).

2. The first argument looks to be "args": {"entity". The arg name is very short, and likely runs into the issue mentioned in my PR where the chunks come back as '"ar' then 'gs": {"ent'. What happens in this case before my fix is that the first argument can be corrupted. I'm not 100% sure if that's what is happening to Sala8888, but it's very common prior to my fix when the first argument is short...

3. What's worse is you can see the full (and correct) arguments get repeated after the first occurrence (right after the first appearance of get_company_funding in the string. This is because the first instance was corrupted from what was in the "expected" string, so the diff calculation is completely wrong, causing the full arguments to be returned in the "closing" part of the tool parser loop.