Fix exception when Logging warning

[aramallo]

The following exception occurs every time the client encounters the OpenAI Chat completion SSE event data: [DONE].

** (exit) an exception was raised:
    ** (Jason.DecodeError) unexpected byte at position 0: 0x64 ("d")
        (jason 1.4.1) lib/jason.ex:92: Jason.decode!/2
        (openai_ex 0.5.8) lib/openai_ex/http_sse.ex:63: OpenaiEx.HttpSse.next_sse/1
        (elixir 1.16.2) lib/stream.ex:1626: Stream.do_resource/5
        (elixir 1.16.2) lib/stream.ex:943: Stream.do_transform/5
        (elixir 1.16.2) lib/stream.ex:1052: Stream.do_transform_inner_enum/7

This happens as the value in the acc is the above string which is not a valid JSON.

  defp next_sse({acc, ref, task}) do
    receive do
      {:chunk, {:data, evt_data}, ^ref} ->
        {tokens, next_acc} = tokenize_data(evt_data, acc)
        {[tokens], {next_acc, ref, task}}

      {:done, ^ref} ->
       # >>>>>>>>>>>>>>>>>>> this call fails
        if acc != "", do: Logger.warning(inspect(Jason.decode!(acc)))
        {:halt, {acc, ref, task}}

      {:canceled, ^ref} ->
        Logger.info("Request canceled by user")
        {:halt, {acc, ref, task}}
    end
  end

The PR changes the above call with:

defp next_sse({acc, ref, task}) do
    receive do
      {:chunk, {:data, evt_data}, ^ref} ->
        {tokens, next_acc} = tokenize_data(evt_data, acc)
        {[tokens], {next_acc, ref, task}}

      {:done, ^ref} when acc == "data: [DONE]" ->
        {:halt, {acc, ref, task}}

      {:done, ^ref} ->
        if acc != "", do: Logger.warning(%{message: "Unexpected value in sse 'acc' after ':done' event received", value: acc})
        {:halt, {acc, ref, task}}

      {:canceled, ^ref} ->
        Logger.info("Request canceled by user")
        {:halt, {acc, ref, task}}
    end
  end

[restlessronin]

@aramallo Thanks for catching this corner case. I hadn't run into a situation where the string was not JSON.

The PR looks ok to me. If you run mix format, I'll merge it.

[restlessronin]

Also, for future reference, could you provide an example where this corner case is exercised.

[aramallo]

Hi @restlessronin ,

Thanks for getting back to me. I will format and resubmit.

BTW, I just spotted another issue.

For example, sending an invalid request now generates the following log

iex(21)> chat_stream = openai |> ChatCompletion.create(chat_req, stream: true)
%{
  status: 400,
  headers: [
    {"date", "Tue, 09 Apr 2024 08:58:57 GMT"},
    {"server", "uvicorn"},
    {"content-length", "147"},
    {"content-type", "application/json"}
  ],
  body_stream: #Function<52.53678557/2 in Stream.resource/3>,
  task_pid: #PID<0.2014.0>
}
iex(22)> chat_stream.body_stream |> Stream.flat_map(& &1) |> Enum.each(fn x -> IO.puts(inspect(x)) end)
2024-04-09 09:58:58.669 [warning] pid=<0.789.0> application=openai_ex module=OpenaiEx.HttpSse function=next_sse/1 line=66
[message: "Unexpected value in sse 'acc' after ':done' event received", value: "{\"object\":\"error\",\"message\":\"Conversation roles must alternate user/assistant/user/assistant/...\",\"type\":\"BadRequestError\",\"param\":null,\"code\":400}"]

I guess this was the purpose of your Logger.warning call in the first place, but the problem is that we are logging a perfectly valid reponse payload and we are not adding it to the request state.

To see what is going on you can check this curl request

.../sn-ml-prompts❯ curl http://localhost:8000/v1/chat/completions \
    -H "Content-Type: application/json" \
    -d '{
        "model": "CodeLlama-34b-Instruct-hf",
        "messages": [
            {"role": "system", "content": "You are a helpful assistant."},{"role": "system", "content": "You are a helpful assistant."},
            {"role": "user", "content": "Who won the world series in 2020?"}
        ],
       "temperature":0,
       "frequency_penalty": 0,
       "presence_penalty":0.1
    }' -v
*   Trying localhost:8000...
* Connected to localhost (localhost) port 8000
> POST /v1/chat/completions HTTP/1.1
> Host: localhost:8000
> User-Agent: curl/8.4.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 385
>
< HTTP/1.1 400 Bad Request
< date: Tue, 09 Apr 2024 08:54:09 GMT
< server: uvicorn
< content-length: 147
< content-type: application/json
<
* Connection #0 to host localhost left intact
{"object":"error","message":"Conversation roles must alternate user/assistant/user/assistant/...","type":"BadRequestError","param":null,"code":400}%

So OpenaiEx will return the following, without the actual error content.

%{
  status: 400,
  headers: [
    {"date", "Tue, 09 Apr 2024 08:36:01 GMT"},
    {"server", "uvicorn"},
    {"content-length", "147"},
    {"content-type", "application/json"}
  ],
  body_stream: #Function<52.53678557/2 in Stream.resource/3>,
  task_pid: #PID<0.2001.0>
}

The ideal would be not to log this as a warning but to add the error event to the body_stream so that we can consume on status != 200 or to returned it the struct like in the following example

%{
  status: 400,
  error: %{
   "message" => "Conversation roles must alternate user/assistant/user/assistant/...",
    "type" => "BadRequestError",
    "param" => null
    } 
  headers: [
    {"date", "Tue, 09 Apr 2024 08:36:01 GMT"},
    {"server", "uvicorn"},
    {"content-length", "147"},
    {"content-type", "application/json"}
  ],
  body_stream: #Function<52.53678557/2 in Stream.resource/3>,
  task_pid: #PID<0.2001.0>
}

[restlessronin]

Hi @aramallo, good points. Most of my personal usage has been in livebook, where the logger warning is sufficient.

In a non-interactive use-case, I was aware that it was likely a problem, but I've hesitated to try to fix it ex-ante. Now that I have a concrete example, and a suggested fix, let me think on this, and get back to you.

[restlessronin]

Hi @aramallo,

If you have a minute could you please provide a test example where the "[[DONE]]" event shows up in the corner case that this PR is fixing?

For completeness.

[aramallo]

Hi @restlessronin thanks for taking this on board. I'll try to reproduce the DONE later on today and send it to you. BTW we are using your lib in a non-interactive way, but so far I really like how it is organised vs other options :-)

[restlessronin]

Hi @restlessronin thanks for taking this on board. I'll try to reproduce the DONE later on today and send it to you. BTW we are using your lib in a non-interactive way, but so far I really like how it is organised vs other options :-)

Fantastic. If you have any other feedback for improvement in non-interactive usage, please add it to this issue

[restlessronin]

Hi @aramallo, I will go ahead and merge this so the PR doesn't remain dangling. I would prefer to have a clear example of the need for handling [[DONE]] before I release it though.

[aramallo]

Thanks a lot @restlessronin and sorry for not getting back on time

[restlessronin]

@aramallo I wound up with an alternate fix for this bug. I don't know if you have had a chance to test 0.5.9 (or 0.6.0 which has breaking FQN module name changes) to make sure your problem remains fixed.