Fix unit tests, trigger completion callback when connection is closed, avoid NPE in client timeout

Open alexis779 opened this issue 1 year ago • 1 comments

This Pull Request handles gracefully errors that can happen while using OpenAI API compatible backends, such as predibase and replicate.

It also fixes some consistently failing unit tests.

Case 1

The problem

When using langchain4j-open-ai library with an Open AI compatible API, such as predibase, we would get a NullPointerException when the client times out. This can be caused by predibase warming up Lora adapter.

2024-07-17T15:58:56.682-07:00 DEBUG 3479431 --- [OpenAI proxy] [edibase.com/...] d.a.openai4j.StreamingRequestExecutor    : onFailure()

java.io.InterruptedIOException: timeout
	at okhttp3.internal.connection.RealCall.timeoutExit(RealCall.kt:398) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.connection.RealCall.callDone(RealCall.kt:360) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.connection.RealCall.noMoreExchanges$okhttp(RealCall.kt:325) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:209) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) ~[okhttp-4.12.0.jar:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]
Caused by: java.io.IOException: Canceled
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) ~[okhttp-4.12.0.jar:na]
	at dev.ai4j.openai4j.RequestLoggingInterceptor.intercept(RequestLoggingInterceptor.java:41) ~[openai4j-0.18.0.jar:na]
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) ~[okhttp-4.12.0.jar:na]
	at dev.ai4j.openai4j.GenericHeaderInjector.intercept(GenericHeaderInjector.java:27) ~[openai4j-0.18.0.jar:na]
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) ~[okhttp-4.12.0.jar:na]
	at dev.ai4j.openai4j.GenericHeaderInjector.intercept(GenericHeaderInjector.java:27) ~[openai4j-0.18.0.jar:na]
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) ~[okhttp-4.12.0.jar:na]
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) ~[okhttp-4.12.0.jar:na]
	... 4 common frames omitted

The fix

Do not log the response when null, which can happen upon a client timeout.

The reproduction case

name: predibase
url: https://serving.app.predibase.com/.../deployments/v2/llms/mistral-7b-instruct-v0-3/v1
token: ...
model: ""

Case 2

The problem

If the server does not send a DONE event at the end of the Server Side Event stream, the client gets stuck for ever.

The fix

Notify the completion callback upon closing the response instead. This finite state machine transition always happens in the SSE stream lifecycle.

The reproduction case

backend: replicate
url: https://openai-proxy.replicate.com/v1
token: ...
model: mistralai/mistral-7b-instruct-v0.2

Unit tests

Some unit tests consistently fail.

Deprecated OpenAI model

The problem

GPT_4_0314 is now deprecated

Caused by: dev.ai4j.openai4j.OpenAiHttpException: {
    "error": {
        "message": "The model `gpt-4-0314` has been deprecated, learn more here: https://platform.openai.com/docs/deprecations",
        "type": "invalid_request_error",
        "param": null,
        "code": "model_not_found"
    }
}

The fix

Just remove this model entry.

Race condition

To test that a request is effectively cancelled, rely on asynchronous callbacks instead of sleeping. Cancel the response once the request started. Use a CompletableFuture to wait for this action. Validate that the request did not complete or error by failing the test within associated callbacks.

Jul 18 '24 05:07 alexis779

Notice the workflow running the tests is now green.

4 occasional failures were addressed as part of this change

Test failure 1

2024-08-24 08:41:24 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.RequestLoggingInterceptor.logDebug()
DEBUG: Request:
- method: POST
- url: https://api.openai.com/v1/chat/completions
- headers: [Accept: text/event-stream], [Authorization: Bearer sk-pr...Sv]
- body: {
  "model": "gpt-4o",
  "messages": [
    {
      "role": "user",
      "content": "What is the weather in Boston?"
    }
  ],
  "stream": true,
  "tools": [
    {
      "type": "function",
      "function": {
        "name": "get_current_weather",
        "description": "Get the current weather in a given location",
        "parameters": {
          "properties": {
            "location": {
              "description": "The city and state, e.g. San Francisco, CA",
              "type": "string"
            },
            "unit": {
              "enum": [
                "CELSIUS",
                "FAHRENHEIT"
              ],
              "type": "string"
            }
          },
          "required": [
            "location",
            "unit"
          ],
          "type": "object"
        }
      }
    }
  ]
}
2024-08-24 08:41:25 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.ResponseLoggingInterceptor.logDebug()
DEBUG: Response:
- status code: 200
- headers: [date: Sat, 24 Aug 2024 15:41:25 GMT], [content-type: text/event-stream; charset=utf-8], [access-control-expose-headers: X-Request-ID], [openai-organization: user-hwntqegcs95ppoyvptv3bbru], [openai-processing-ms: 198], [openai-version: 2020-10-01], [strict-transport-security: max-age=15552000; includeSubDomains; preload], [x-ratelimit-limit-requests: 5000], [x-ratelimit-limit-tokens: 450000], [x-ratelimit-remaining-requests: 4999], [x-ratelimit-remaining-tokens: 449975], [x-ratelimit-reset-requests: 12ms], [x-ratelimit-reset-tokens: 3ms], [x-request-id: req_016d6ec38a3c606709c94ff21f244ef5], [cf-cache-status: DYNAMIC], [set-cookie: __cf_bm=iuxtu9jfPnVK2tKZA0DJQSmb_fUNQ7SAR210YP8ZvEo-1724514085-1.0.1.1-q.4PhAPuc.U.MIK_R5452zMwyCisf6n2MLCzacukckd2NsW3xYB9So4QAdUTep.9Ps5McahWC6GbTbuX.Xxtmw; path=/; expires=Sat, 24-Aug-24 16:11:25 GMT; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [x-content-type-options: nosniff], [set-cookie: _cfuvid=PJvhp7ZbcU.idq2JJqSrVGtbfqtUPqPzMW5F4vN2Dyo-1724514085113-0.0.1.1-604800000; path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [server: cloudflare], [cf-ray: 8b847245ff13cf21-SJC], [alt-svc: h3=":443"; ma=86400]
- body: [skipping response body due to streaming]
2024-08-24 08:41:25 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.ResponseLoggingInterceptor.logDebug()
DEBUG: Response:
- status code: 200
- headers: [date: Sat, 24 Aug 2024 15:41:25 GMT], [content-type: text/event-stream; charset=utf-8], [access-control-expose-headers: X-Request-ID], [openai-organization: user-hwntqegcs95ppoyvptv3bbru], [openai-processing-ms: 198], [openai-version: 2020-10-01], [strict-transport-security: max-age=15552000; includeSubDomains; preload], [x-ratelimit-limit-requests: 5000], [x-ratelimit-limit-tokens: 450000], [x-ratelimit-remaining-requests: 4999], [x-ratelimit-remaining-tokens: 449975], [x-ratelimit-reset-requests: 12ms], [x-ratelimit-reset-tokens: 3ms], [x-request-id: req_016d6ec38a3c606709c94ff21f244ef5], [cf-cache-status: DYNAMIC], [set-cookie: __cf_bm=iuxtu9jfPnVK2tKZA0DJQSmb_fUNQ7SAR210YP8ZvEo-1724514085-1.0.1.1-q.4PhAPuc.U.MIK_R5452zMwyCisf6n2MLCzacukckd2NsW3xYB9So4QAdUTep.9Ps5McahWC6GbTbuX.Xxtmw; path=/; expires=Sat, 24-Aug-24 16:11:25 GMT; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [x-content-type-options: nosniff], [set-cookie: _cfuvid=PJvhp7ZbcU.idq2JJqSrVGtbfqtUPqPzMW5F4vN2Dyo-1724514085113-0.0.1.1-604800000; path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [server: cloudflare], [cf-ray: 8b847245ff13cf21-SJC], [alt-svc: h3=":443"; ma=86400]
- body: [skipping response body due to streaming]
2024-08-24 08:41:25 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znBEdBGQC1DInKaYBwklg9A6vWc5","object":"chat.completion.chunk","created":1724514084,"model":"gpt-4o-2024-05-13","system_fingerprint":"fp_3aa7262c27","choices":[{"index":0,"delta":{"role":"assistant","content":"","refusal":null},"logprobs":null,"finish_reason":null}]}
Exception in thread "OkHttp Dispatcher" org.opentest4j.AssertionFailedError:
expected: null
 but was: ""
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502)
	at dev.ai4j.openai4j.chat.ChatCompletionStreamingTest.lambda$testTools$3(ChatCompletionStreamingTest.java:147)
	at dev.ai4j.openai4j.StreamingRequestExecutor$2.onEvent(StreamingRequestExecutor.java:177)
	at okhttp3.internal.sse.RealEventSource.onEvent(RealEventSource.kt:101)
	at okhttp3.internal.sse.ServerSentEventReader.completeEvent(ServerSentEventReader.kt:108)
	at okhttp3.internal.sse.ServerSentEventReader.processNextEvent(ServerSentEventReader.kt:52)
	at okhttp3.internal.sse.RealEventSource.processResponse(RealEventSource.kt:75)
	at okhttp3.internal.sse.RealEventSource.onResponse(RealEventSource.kt:46)
	at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:519)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1570)

java.util.concurrent.TimeoutException
	at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1960)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2095)
	at dev.ai4j.openai4j.chat.ChatCompletionStreamingTest.testTools(ChatCompletionStreamingTest.java:186)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)

Mitigation

Checking for null or empty string, instead of just null, fixes the issue

assertThat(delta.functionCall()).isIn(null, "");

Test Failure 2

2024-08-24 08:49:43 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.RequestLoggingInterceptor.logDebug()
DEBUG: Request:
- method: POST
- url: https://api.openai.com/v1/chat/completions
- headers: [Accept: text/event-stream], [Authorization: Bearer sk-pr...Sv]
- body: {
  "model": "gpt-3.5-turbo-1106",
  "messages": [
    {
      "role": "user",
      "content": "What is the weather in Boston?"
    }
  ],
  "stream": true,
  "tools": [
    {
      "type": "function",
      "function": {
        "name": "get_current_weather",
        "description": "Get the current weather in a given location",
        "parameters": {
          "properties": {
            "location": {
              "description": "The city and state, e.g. San Francisco, CA",
              "type": "string"
            },
            "unit": {
              "enum": [
                "CELSIUS",
                "FAHRENHEIT"
              ],
              "type": "string"
            }
          },
          "required": [
            "location",
            "unit"
          ],
          "type": "object"
        }
      }
    }
  ]
}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.ResponseLoggingInterceptor.logDebug()
DEBUG: Response:
- status code: 200
- headers: [date: Sat, 24 Aug 2024 15:49:44 GMT], [content-type: text/event-stream; charset=utf-8], [access-control-expose-headers: X-Request-ID], [openai-organization: user-hwntqegcs95ppoyvptv3bbru], [openai-processing-ms: 865], [openai-version: 2020-10-01], [strict-transport-security: max-age=15552000; includeSubDomains; preload], [x-ratelimit-limit-requests: 5000], [x-ratelimit-limit-tokens: 2000000], [x-ratelimit-remaining-requests: 4999], [x-ratelimit-remaining-tokens: 1999975], [x-ratelimit-reset-requests: 12ms], [x-ratelimit-reset-tokens: 0s], [x-request-id: req_aa32450f99f06dc6f514afbaf2b21e8d], [cf-cache-status: DYNAMIC], [set-cookie: __cf_bm=3g1mpmW9zJAsPOEWLJyyXFiMciLPJ6WlVc6KX72o8bA-1724514584-1.0.1.1-UKcRBLSUqYkF6Vu4Kc8cqCbTtwmHmpArSIpA1271JVe45mtzJg.VXB0bFUclqDPedgA_3n9omqtBqOyw.QQKkw; path=/; expires=Sat, 24-Aug-24 16:19:44 GMT; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [x-content-type-options: nosniff], [set-cookie: _cfuvid=KN.SUC.NrsrmhzcUSjb9zoG9uTWXhgjodtwp2rJFiRI-1724514584609-0.0.1.1-604800000; path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [server: cloudflare], [cf-ray: 8b847e731f132530-SJC], [alt-svc: h3=":443"; ma=86400]
- body: [skipping response body due to streaming]
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.ResponseLoggingInterceptor.logDebug()
DEBUG: Response:
- status code: 200
- headers: [date: Sat, 24 Aug 2024 15:49:44 GMT], [content-type: text/event-stream; charset=utf-8], [access-control-expose-headers: X-Request-ID], [openai-organization: user-hwntqegcs95ppoyvptv3bbru], [openai-processing-ms: 865], [openai-version: 2020-10-01], [strict-transport-security: max-age=15552000; includeSubDomains; preload], [x-ratelimit-limit-requests: 5000], [x-ratelimit-limit-tokens: 2000000], [x-ratelimit-remaining-requests: 4999], [x-ratelimit-remaining-tokens: 1999975], [x-ratelimit-reset-requests: 12ms], [x-ratelimit-reset-tokens: 0s], [x-request-id: req_aa32450f99f06dc6f514afbaf2b21e8d], [cf-cache-status: DYNAMIC], [set-cookie: __cf_bm=3g1mpmW9zJAsPOEWLJyyXFiMciLPJ6WlVc6KX72o8bA-1724514584-1.0.1.1-UKcRBLSUqYkF6Vu4Kc8cqCbTtwmHmpArSIpA1271JVe45mtzJg.VXB0bFUclqDPedgA_3n9omqtBqOyw.QQKkw; path=/; expires=Sat, 24-Aug-24 16:19:44 GMT; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [x-content-type-options: nosniff], [set-cookie: _cfuvid=KN.SUC.NrsrmhzcUSjb9zoG9uTWXhgjodtwp2rJFiRI-1724514584609-0.0.1.1-604800000; path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [server: cloudflare], [cf-ray: 8b847e731f132530-SJC], [alt-svc: h3=":443"; ma=86400]
- body: [skipping response body due to streaming]
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"role":"assistant","content":null},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"id":"call_AOrzSNGpKYKIMxbf0ogb4eqP","type":"function","function":{"name":"get_current_weather","arguments":""}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"{\"lo"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"catio"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"n\": \"B"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"osto"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"n, MA"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"\", \"un"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"it\":"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":" \"CEL"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"SIUS\"}"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"id":"call_CX1gkGxBmkpvQuENsHeKS0MX","type":"function","function":{"name":"get_current_weather","arguments":""}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"{\"lo"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"catio"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"n\": \"B"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"osto"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"n, MA"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"\", \"un"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"it\":"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":" \"FAH"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"RENHEI"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{"tool_calls":[{"index":1,"function":{"arguments":"T\"}"}}]},"logprobs":null,"finish_reason":null}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() {"id":"chatcmpl-9znJHIkEzLkYmOQy7Pd2vkt6FAdXq","object":"chat.completion.chunk","created":1724514583,"model":"gpt-3.5-turbo-1106","system_fingerprint":"fp_5aa43294a1","choices":[{"index":0,"delta":{},"logprobs":null,"finish_reason":"tool_calls"}]}
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onEvent()
DEBUG: onEvent() [DONE]
2024-08-24 08:49:44 [OkHttp https://api.openai.com/...] dev.ai4j.openai4j.StreamingRequestExecutor.onClosed()
DEBUG: onClosed()

org.opentest4j.AssertionFailedError:
expected: "get_current_weather"
 but was: "get_current_weatherget_current_weather"
Expected :"get_current_weather"
Actual   :"get_current_weatherget_current_weather"
<Click to see difference>


	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502)
	at dev.ai4j.openai4j.chat.ChatCompletionStreamingTest.testTools(ChatCompletionStreamingTest.java:198)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)

Mitigation

ChatGPT 3.5 tend to return 2 function calls for both units while only 1 was expected by the test. This happens when the prompt does not specify whether the user wants Fahrenheit or Celsius, even though Boston location in the input would indicate it should be Fahrenheit.

Skipping the 2nd function call by checking the index avoids this duplicated function name result (get_current_weatherget_current_weather).

                        if (toolCall.index() > 0) {
                            // skip other function candidates
                            return;
                        }

Test failure 3

2024-08-24 17:32:17 [main] dev.ai4j.openai4j.RequestLoggingInterceptor.logDebug()
DEBUG: Request:
- method: POST
- url: http://langchain4j.dev:8082/v1/chat/completions
- headers: [Authorization: ***
- body: {
  "model": "gpt-3.5-turbo-1106",
  "messages": [
    {
      "role": "user",
      "content": "What is the weather in Boston?"
    },
    {
      "role": "assistant",
      "content": null,
      "tool_calls": [
        {
          "id": "call_xkbgDwXqaPcaHWts3b8foba3",
          "type": "function",
          "function": {
            "name": "get_current_weather",
            "arguments": "{\"location\": \"Boston, MA\", \"unit\": \"CELSIUS\"}"
          }
        },
        {
          "id": "call_wSdt6TRT59z5nb81YIubQTq3",
          "type": "function",
          "function": {
            "name": "get_current_weather",
            "arguments": "{\"location\": \"Boston, MA\", \"unit\": \"FAHRENHEIT\"}"
          }
        }
      ]
    },
    {
      "role": "tool",
      "tool_call_id": "call_xkbgDwXqaPcaHWts3b8foba3",
      "content": "{\"temperature\": 11,\"unit\":\"celsius\",\"description\":\"Foggy\"}"
    }
  ]
}

Error:    ChatCompletionTest.testTools:147 » OpenAiHttp {
  "error": {
    "message": "An assistant message with 'tool_calls' must be followed by tool messages responding to each 'tool_call_id'. The following tool_call_ids did not have response messages: call_wSdt6TRT59z5nb81YIubQTq3",
    "type": "invalid_request_error",
    "param": "messages",
    "code": null
  }
}

Mitigation

Notice there are 2 tool calls in the assistant message but only 1 tool message. OpenAI expects the tool message count to match the assistant message tool call count. Adding 1 tool message for the Fahrenheit unit fixes the error.

Test failure 4

2024-08-24 10:46:54 [main] dev.ai4j.openai4j.RequestLoggingInterceptor.logDebug()
DEBUG: Request:
- method: POST
- url: https://api.openai.com/v1/chat/completions
- headers: [Authorization: Bearer sk-pr...Sv]
- body: {
  "model": "gpt-4o-2024-08-06",
  "messages": [
    {
      "role": "user",
      "content": "What is the weather in Boston?"
    }
  ],
  "tools": [
    {
      "type": "function",
      "function": {
        "name": "get_current_weather",
        "description": "Get the current weather in a given location",
        "parameters": {
          "properties": {
            "location": {
              "description": "The city and state, e.g. San Francisco, CA",
              "type": "string"
            },
            "unit": {
              "enum": [
                "CELSIUS",
                "FAHRENHEIT"
              ],
              "type": "string"
            }
          },
          "required": [
            "location",
            "unit"
          ],
          "type": "object"
        }
      }
    }
  ]
}
2024-08-24 10:46:55 [main] dev.ai4j.openai4j.ResponseLoggingInterceptor.logDebug()
DEBUG: Response:
- status code: 200
- headers: [date: Sat, 24 Aug 2024 17:46:55 GMT], [content-type: application/json], [access-control-expose-headers: X-Request-ID], [openai-organization: user-hwntqegcs95ppoyvptv3bbru], [openai-processing-ms: 205], [openai-version: 2020-10-01], [strict-transport-security: max-age=15552000; includeSubDomains; preload], [x-ratelimit-limit-requests: 5000], [x-ratelimit-limit-tokens: 450000], [x-ratelimit-remaining-requests: 4999], [x-ratelimit-remaining-tokens: 449975], [x-ratelimit-reset-requests: 12ms], [x-ratelimit-reset-tokens: 3ms], [x-request-id: req_17380022ee2055d4789e02050c01c37b], [cf-cache-status: DYNAMIC], [set-cookie: __cf_bm=_KyUqKs0mGIJHl6dkt10iz.O9PwtDQ9G3S9R_QsFH_I-1724521615-1.0.1.1-e5nr0Qb5oFuK3Kew9jfFfWaKTZkPFt4j19qqwWzTT8yOf08QGxtaArALy3aEuHA3sRp3kgpc8b3pNtS7wzLn8w; path=/; expires=Sat, 24-Aug-24 18:16:55 GMT; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [x-content-type-options: nosniff], [set-cookie: _cfuvid=0vJJHH2agJ7p5yeN34bpclWMeHCbi7pdI8jNvLPFZzI-1724521615465-0.0.1.1-604800000; path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None], [server: cloudflare], [cf-ray: 8b852a1d8ffe67af-SJC], [alt-svc: h3=":443"; ma=86400]
- body: {
  "id": "chatcmpl-9zp8hbebn3CFXr4EaBjK85qo39h3A",
  "object": "chat.completion",
  "created": 1724521615,
  "model": "gpt-4o-2024-08-06",
  "choices": [
    {
      "index": 0,
      "message": {
        "role": "assistant",
        "content": "What's the temperature unit you prefer, Celsius or Fahrenheit?",
        "refusal": null
      },
      "logprobs": null,
      "finish_reason": "stop"
    }
  ],
  "usage": {
    "prompt_tokens": 83,
    "completion_tokens": 12,
    "total_tokens": 95
  },
  "system_fingerprint": "fp_2a322c9ffc"
}


org.opentest4j.AssertionFailedError:
expected: null
 but was: "What's the temperature unit you prefer, Celsius or Fahrenheit?"
Expected :null
Actual   :"What's the temperature unit you prefer, Celsius or Fahrenheit?"
<Click to see difference>


	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502)
	at dev.ai4j.openai4j.chat.ChatCompletionTest.testTools(ChatCompletionTest.java:118)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)

Mitigation

There's ambiguity in the prompt. ChatGPT model may decide to choose the correct unit or confirm with the user.

Specifying the unit in the prompt remove the ambiguity:

What is the weather in Boston in Celsius?

Aug 28 '24 16:08 alexis779