@Document objects sometimes not reading the @Reference associations, Which leads to JsonSyntaxException

[abilash-sethu]

We've been working on a project where we use @reference with @document models a lot, In some of the documents even have more than 10+ @reference associations.

Sometimes when we use RedisDocumentRepository/EntitiyStream to read such documents from redis, We get the following error

com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 424 path $.vehicleMake at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:397) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.readIntoField(ReflectiveTypeAdapterFactory.java:212) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$FieldReflectionAdapter.readField(ReflectiveTypeAdapterFactory.java:433) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:393) at com.google.gson.Gson.fromJson(Gson.java:1227) at com.google.gson.Gson.fromJson(Gson.java:1137) at com.google.gson.Gson.fromJson(Gson.java:1047) at com.google.gson.Gson.fromJson(Gson.java:982) at com.redis.om.spring.repository.query.RediSearchQuery.executeQuery(RediSearchQuery.java:462) at com.redis.om.spring.repository.query.RediSearchQuery.execute(RediSearchQuery.java:360) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:136) at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:120) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164) at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:72) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:244) at jdk.proxy2/jdk.proxy2.$Proxy235.findByEnterpriseIdAndSurId(Unknown Source) at jdk.internal.reflect.GeneratedMethodAccessor88.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343)

The document is Vehicle document has 10+ associations, vehicle make is one of them. When we debug this on Google GSON library, We saw that the above vehicleMake association is coming as null in all fields. At the same time, some @reference associations are fetching correctly, We verified the reference ids in the other hand of the cache, Everything seems ok

The weird thing is it is not happening all the time, So we are very confused, We assumed this could be due to network/server issues, We added more server resources and restarted the services, Still often we are getting this issue in many places not only with vehicle document.

Versions Used

Spring boot: 3.1.3
Redis Om Spring: 0.8.7
RediSearch : 2.8.9
RedisJSON : 2.6.7

@bsbodden Any help would be greatly appreciated

[bsbodden]

@abilash-sethu happy to assist... First we need to recreate the conditions to be able to recreate the issue. Could you put a bare-bones Redis OM Spring App with a toy model that resembles the one in production and perhaps a few of the operations causing trouble. If such an example can be assembled I can start working towards a solution. Cheers!

[abilash-sethu]

@bsbodden Thanks for the response, Will try to prepare something and get back to you

[abilash-sethu]

@bsbodden Sorry for the delay, We were doing a lot of tests to see whether the same issue is coming, And yes it is coming very often now, In many places. It was a challenge to create a POC that regenerates the same issue. I've managed to set up a small project which replicates the same cache structure as we have. There is a scheduler in the controller which runs frequently and fetches the data, In the startup I can see the issue is throwing.

1. Replace the Redis config
2. Run the spring boot application
3. Load the test data by calling the API: /prepare-data
4. Read the data using the API: /vehicles
5. Try to restart the service frequently till you get the below exception

com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 251 path $.capacityUnit at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:397) ~[gson-2.10.1.jar:na] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.readIntoField(ReflectiveTypeAdapterFactory.java:212) ~[gson-2.10.1.jar:na] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$FieldReflectionAdapter.readField(ReflectiveTypeAdapterFactory.java:433) ~[gson-2.10.1.jar:na] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:393) ~[gson-2.10.1.jar:na] at com.google.gson.Gson.fromJson(Gson.java:1227) ~[gson-2.10.1.jar:na] at com.google.gson.Gson.fromJson(Gson.java:1137) ~[gson-2.10.1.jar:na] at com.google.gson.Gson.fromJson(Gson.java:1047) ~[gson-2.10.1.jar:na] at com.google.gson.Gson.fromJson(Gson.java:982) ~[gson-2.10.1.jar:na] at com.redis.om.spring.RedisJSONKeyValueAdapter.lambda$getAllOf$2(RedisJSONKeyValueAdapter.java:168) ~[redis-om-spring-0.8.7.jar:na] at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) ~[na:na] at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625) ~[na:na] at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[na:na] at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:575) ~[na:na] at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622) ~[na:na] at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627) ~[na:na] at com.redis.om.spring.RedisJSONKeyValueAdapter.getAllOf(RedisJSONKeyValueAdapter.java:169) ~[redis-om-spring-0.8.7.jar:na] at org.springframework.data.redis.core.RedisKeyValueAdapter.getAllOf(RedisKeyValueAdapter.java:337) ~[spring-data-redis-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.core.KeyValueTemplate.lambda$findAll$2(KeyValueTemplate.java:216) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.core.KeyValueTemplate.execute(KeyValueTemplate.java:314) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.core.KeyValueTemplate.executeRequired(KeyValueTemplate.java:329) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.core.KeyValueTemplate.findAll(KeyValueTemplate.java:214) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.repository.support.SimpleKeyValueRepository.findAll(SimpleKeyValueRepository.java:108) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at org.springframework.data.keyvalue.repository.support.SimpleKeyValueRepository.findAll(SimpleKeyValueRepository.java:42) ~[spring-data-keyvalue-3.1.3.jar:3.1.3] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na] at org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryFragmentMethodInvoker.lambda$new$0(RepositoryMethodInvoker.java:288) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:136) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:120) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:516) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:285) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:628) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:168) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:143) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:72) ~[spring-data-commons-3.1.3.jar:3.1.3] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:244) ~[spring-aop-6.0.11.jar:6.0.11] at jdk.proxy2/jdk.proxy2.$Proxy104.findAll(Unknown Source) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:196) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ~[spring-tx-6.0.11.jar:6.0.11] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:244) ~[spring-aop-6.0.11.jar:6.0.11] at jdk.proxy2/jdk.proxy2.$Proxy104.findAll(Unknown Source) ~[na:na] at com.example.redis.tests.controller.TestController.getAllVehicles(TestController.java:65) ~[classes/:na] at com.example.redis.tests.controller.TestController.init(TestController.java:45) ~[classes/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na] at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-6.0.11.jar:6.0.11] at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.0.11.jar:6.0.11] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na] at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[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:833) ~[na:na] Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 251 path $.capacityUnit at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:393) ~[gson-2.10.1.jar:na] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:386) ~[gson-2.10.1.jar:na]

IMPORTANT: The issue only occurs on the startup in this demo, But in our real project we get these issues in runtime

Another additional piece of info is we run the Redis on docker container using the below command

docker run -e REDIS_ARGS="--requirepass admin" -d --name redis-stack -p 6379:6379 -p 8001:8001 <IMAGE>

Here is the version details:

redis-tests-403.zip

[bsbodden]

@abilash-sethu we'll start looking into it. Thanks for the report!

[Salman83]

I also faced this issue... I hope the issue get resolved soon.

[bsbodden]

@abilash-sethu I haven't been able to trigger the exception on my system yet. Until I can get a demonstrable error to fix I just wanted to drop a few observations...

• @Reference is provided by Spring Data Redis, and I provided a mirror implementation for @Document annotated entities using GSon under the covers. But I'm leery of associations in a NoSQL DB...
• @Reference is to be used with care, and IMO rarely. Since each call time you load an entity you'll have 1+N calls if you have N references - if you're doing a findAll you have M × (N+1)
• Since this is NoSQL db I would recommend denormalization, evaluate which references can be directly embedded in the document
• I have an open issue to implement caching of the rehydrated references and therefore minimize the number of redis calls for the references in a findAll and perhaps execute query instances

I will try to write a different test to try to recreate the condition, my guess is that something in GSon can handle the rapid fire, so a try/catch, retry or protected code block to handle the deserialization might be the cure

[bsbodden]

@abilash-sethu @Salman83 Could either of you or both test your code against this PR #431 - I believe the changes in it might solve all of your @reference problems.

[abilash-sethu]

@bsbodden Thanks for the report, Will test them and get back to you

[bsbodden]

The potential fix is included in the latest release. Please test with the Release v0.9.1 - Thanks

[bsbodden]

@abilash-sethu @Salman83 Please let us know if this fixed your issues. Thanks!

[abilash-sethu]

@bsbodden Sorry for the delay, I did some tests, But unfortunately, I still face the issue, I'll put the full server logs here, Might be helpful for you to understand more

issue-403-log.txt

See the updated POM

[bsbodden]

@abilash-sethu since I haven't been able to reproduce this, here's what my ask is, can we do a uber-minimal example, 1 model, no web interface, just a CommandLineRunner in the main app with a tight-loop to try to replicate. If you can put that together it would really accelerate finding the root cause. Thanks

[abilash-sethu]

@bsbodden I'll give it a try and get back to you

[abilash-sethu]

@bsbodden Sorry for the delay, With minimal data/indexes/reads, it looks like not reproducing