The streamFunctionCallTest failed in CI and also on my local machine.
I disabled it but then OllamaChatModelIT.mapOutputConvert failed in CI, but not on my local machine.
here are the errors
Error: Errors:
Error: org.springframework.ai.ollama.OllamaChatModelFunctionCallingIT.streamFunctionCallTest
Error: Run 1: OllamaChatModelFunctionCallingIT.streamFunctionCallTest:109
There is also this error, not related but should be looked at. It seems it can't connect to ollama, but the message is null, so probably something needs to be improved not just here since most chat models follow a similar code path.
2024-12-08T22:32:46.960Z INFO 4348 --- [ main] o.s.ai.ollama.OllamaChatModelIT : Starting OllamaChatModelIT using Java 17.0.13 with PID 4348 (started by runner in /home/runner/work/spring-ai/spring-ai/models/spring-ai-ollama)
2024-12-08T22:32:46.960Z INFO 4348 --- [ main] o.s.ai.ollama.OllamaChatModelIT : No active profile set, falling back to 1 default profile: "default"
2024-12-08T22:32:46.981Z INFO 4348 --- [ main] tc.ollama/ollama:0.3.14 : Creating container for image: ollama/ollama:0.3.14
2024-12-08T22:32:47.002Z INFO 4348 --- [ main] tc.ollama/ollama:0.3.14 : Container ollama/ollama:0.3.14 is starting: 1113c49b1dead7d55dd6cdde03cd95fbcc226f38cc5df799a024a9eefc56a2bd
2024-12-08T22:32:47.284Z INFO 4348 --- [ main] tc.ollama/ollama:0.3.14 : Container ollama/ollama:0.3.14 started in PT0.303834581S
2024-12-08T22:32:47.292Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Start pulling model: llama3.2
2024-12-08T22:32:48.743Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling manifest
2024-12-08T22:32:54.416Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling dde5aa3fc5ff
2024-12-08T22:32:56.286Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling 966de95ca8a6
2024-12-08T22:32:58.196Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling fcc5a6bec9da
2024-12-08T22:33:00.150Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling a70ff7e570d9
2024-12-08T22:33:01.988Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling 56bb8bd477a5
2024-12-08T22:33:02.956Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: pulling 34bb5ab01051
2024-12-08T22:33:04.480Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: verifying sha256 digest
2024-12-08T22:33:04.480Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: writing manifest
2024-12-08T22:33:04.481Z INFO 4348 --- [ent-20-Worker-0] o.s.a.o.management.OllamaModelManager : Pulling the 'llama3.2' model - Status: success
2024-12-08T22:33:04.481Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Completed pulling the 'llama3.2' model
2024-12-08T22:33:04.485Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Start pulling model: tinyllama
2024-12-08T22:33:05.762Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling manifest
2024-12-08T22:33:09.658Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling 2af3b81862c6
2024-12-08T22:33:11.527Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling af0ddbdaaa26
2024-12-08T22:33:13.480Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling c8472cd9daed
2024-12-08T22:33:15.511Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling fa956ab37b8c
2024-12-08T22:33:16.482Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: pulling 6331358be52a
2024-12-08T22:33:16.962Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: verifying sha256 digest
2024-12-08T22:33:16.962Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: writing manifest
2024-12-08T22:33:16.962Z INFO 4348 --- [ent-20-Worker-2] o.s.a.o.management.OllamaModelManager : Pulling the 'tinyllama' model - Status: success
2024-12-08T22:33:16.962Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Completed pulling the 'tinyllama' model
2024-12-08T22:33:16.966Z INFO 4348 --- [ main] o.s.ai.ollama.OllamaChatModelIT : Started OllamaChatModelIT in 30.022 seconds (process running for 550.688)
2024-12-08T22:36:39.382Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Start deletion of model: tinyllama
2024-12-08T22:36:39.501Z INFO 4348 --- [ main] o.s.a.o.management.OllamaModelManager : Completed deletion of model: tinyllama
[INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 252.2 s -- in org.springframework.ai.ollama.OllamaChatModelIT
[INFO] Running org.springframework.ai.ollama.OllamaChatModelFunctionCallingIT
2024-12-08T22:36:59.133Z ERROR 4348 --- [onPool-worker-5] o.s.ai.chat.model.MessageAggregator : Aggregation Error
org.springframework.web.reactive.function.client.WebClientRequestException: null
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:136) ~[spring-webflux-6.1.15.jar:6.1.15]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
*__checkpoint ⇢ Request to POST http://localhost:32768/api/chat [DefaultWebClient]
Original Stack Trace:
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:136) ~[spring-webflux-6.1.15.jar:6.1.15]
at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.Mono.subscribe(Mono.java:4576) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:280) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.MonoCompletionStage$MonoCompletionStageSubscription.apply(MonoCompletionStage.java:115) ~[reactor-core-3.6.12.jar:3.6.12]
at reactor.core.publisher.MonoCompletionStage$MonoCompletionStageSubscription.apply(MonoCompletionStage.java:67) ~[reactor-core-3.6.12.jar:3.6.12]
at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.postFire(CompletableFuture.java:614) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:844) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$Completion.exec(CompletableFuture.java:483) ~[na:na]
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373) ~[na:na]
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182) ~[na:na]
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655) ~[na:na]
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622) ~[na:na]
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165) ~[na:na]
Caused by: java.net.ConnectException: null
at java.net.http/jdk.internal.net.http.common.Utils.toConnectException(Utils.java:1083) ~[java.net.http:na]
at java.net.http/jdk.internal.net.http.PlainHttpConnection.connectAsync(PlainHttpConnection.java:198) ~[java.net.http:na]
at java.net.http/jdk.internal.net.http.PlainHttpConnection.checkRetryConnect(PlainHttpConnection.java:230) ~[java.net.http:na]
at java.net.http/jdk.internal.net.http.PlainHttpConnection.lambda$connectAsync$1(PlainHttpConnection.java:206) ~[java.net.http:na]
at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773) ~[na: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.nio.channels.ClosedChannelException: null
at java.base/sun.nio.ch.SocketChannelImpl.ensureOpen(SocketChannelImpl.java:195) ~[na:na]
at java.base/sun.nio.ch.SocketChannelImpl.beginConnect(SocketChannelImpl.java:760) ~[na:na]
at java.base/sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:848) ~[na:na]
at java.net.http/jdk.internal.net.http.PlainHttpConnection.lambda$connectAsync$0(PlainHttpConnection.java:183) ~[java.net.http:na]
at java.base/java.security.AccessController.doPrivileged(AccessController.java:569) ~[na:na]
at java.net.http/jdk.internal.net.http.PlainHttpConnection.connectAsync(PlainHttpConnection.java:185) ~[java.net.http:na]
... 9 common frames omitted
and
Error: Tests run: 8, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 251.6 s <<< FAILURE! -- in org.springframework.ai.ollama.OllamaChatModelIT
Error: org.springframework.ai.ollama.OllamaChatModelIT.mapOutputConvert -- Time elapsed: 7.332 s <<< ERROR!
org.springframework.messaging.converter.MessageConversionException:
Could not read JSON: Unexpected end-of-input: expected close marker for Object (start marker at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 1, column: 1])
at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 4, column: 14], failedMessage=GenericMessage [payload=byte[45], headers={id=f2d2cf26-4ff0-4a32-ebd5-f23ce0a074a7, timestamp=1733715502608}]
at org.springframework.messaging.converter.MappingJackson2MessageConverter.convertFromInternal(MappingJackson2MessageConverter.java:256)
at org.springframework.messaging.converter.AbstractMessageConverter.fromMessage(AbstractMessageConverter.java:183)
at org.springframework.messaging.converter.AbstractMessageConverter.fromMessage(AbstractMessageConverter.java:174)
at org.springframework.ai.converter.MapOutputConverter.convert(MapOutputConverter.java:49)
at org.springframework.ai.ollama.OllamaChatModelIT.mapOutputConvert(OllamaChatModelIT.java:178)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
Caused by: com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: expected close marker for Object (start marker at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 1, column: 1])
at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 4, column: 14]
at com.fasterxml.jackson.core.base.ParserMinimalBase._reportInvalidEOF(ParserMinimalBase.java:585)
at com.fasterxml.jackson.core.base.ParserBase._handleEOF(ParserBase.java:535)
at com.fasterxml.jackson.core.base.ParserBase._eofAsNextChar(ParserBase.java:552)
at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._skipWSOrEnd(UTF8StreamJsonParser.java:3066)
at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.nextFieldName(UTF8StreamJsonParser.java:999)
at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:608)
at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:449)
at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:32)
at com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:342)
at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4899)
at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3940)
at org.springframework.messaging.converter.MappingJackson2MessageConverter.convertFromInternal(MappingJackson2MessageConverter.java:242)
... 7 more
Comment From: markpollack
The test fails as well on my local machine, seems like the response is the really the xml to call the tool.
2024-12-08T22:08:53.247-05:00 INFO 998046 --- [ main] o.s.a.o.OllamaChatModelFunctionCallingIT : Response: <tool_call>
{"name": "getCurrentWeather", "arguments": {"location": "San Francisco, CA", "unit": "C"}}
</tool_call>
ază
Get current weather information for location: San Francisco, CA with unit C.
<tool_call>
{"name": "getCurrentWeather", "arguments": {"location": "Tokyo, JP", "unit": "C"}}
</tool_call>
ază
Get current weather information for location: Tokyo, JP with unit C.
<tool_call>
{"name": "getCurrentWeather", "arguments": {"location": "Paris, FR", "unit": "C"}}
</tool_call>
Unrelated to function calling when streaming, but to hopefully add stability in CI, I've added the env var OLLAMA_WITH_REUSE=true to the github action for running the CI tests. It doesn't address the issue in question, but perhaps will reduce it's frequency as the model isn't getting pulled over and over again, maybe there is a timing issue in terms of when starts serving the model and that is why there was a connection exception.
Comment From: tzolov
The Ollama streaming tests failures should be resolved by : https://github.com/spring-projects/spring-ai/commit/9f775ab2c24b3b25a733bb5ca34ed663eb7d3e93 It was due to an outdated ollama docker images