MappingJackson2HttpMessageConverter should not always log a warning [SPR-14163]

[spring-projects-issues]

Claes Mogren opened SPR-14163 and commented

We have a project that registers both a MappingJackson2HttpMessageConverter and a ProtobufHttpMessageConverter to our RestTemplate. This works fine, but every time we de-serialize a JSON body into a protobuf we get something like:

2016-04-13 13:22:30.760 WARN [app-service] 15947 --- [AppClient-1] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]

It can of course be hidden by setting logging.level.org.springframework.http.converter.json: 'ERROR' in our application.yml, but it's not the solution.

---

Affects: 4.1.7

Reference URL: https://github.com/spring-projects/spring-framework/blob/master/spring-web/src/main/java/org/springframework/http/converter/json/AbstractJackson2HttpMessageConverter.java#L156

Issue Links:

• Log caught exception in MappingJackson2HttpMessageConverter [SPR-11403] #16030 Log caught exception in MappingJackson2HttpMessageConverter
• MappingJackson2(Http)MessageConverter should be more verbose in canRead/canWrite checks (on Jackson 2.3) [SPR-11261] #15886 MappingJackson2(Http)MessageConverter should be more verbose in canRead/canWrite checks (on Jackson 2.3)
• Poor diagnostics when Jackson cannot deserialise an application/json payload due to a missing deserialiser [SPR-15582] #20141 Poor diagnostics when Jackson cannot deserialise an application/json payload due to a missing deserialiser
• AbstractJackson2HttpMessageConverter incorrectly logs at WARN level after upgrading to Jackson 2.9 [SPR-16947] #21486 AbstractJackson2HttpMessageConverter incorrectly logs at WARN level after upgrading to Jackson 2.9

Referenced from: commits 62ce9af, bf3cadb, e366746, 5f4e838, 334b4a9

[spring-projects-issues]

Juergen Hoeller commented

I suppose we could add a flag to MappingJackson2HttpMessageConverter, allowing to suppress that specific warning.

Have you tried ordering your converters accordingly? So that if the Protobuf converter comes first, the Jackson converter wouldn't even see those types?

[spring-projects-issues]

Claes Mogren commented

I tried that first, the complete code block for the restTemplate is:

    @Bean
    public RestTemplate restTemplate(ProtobufHttpMessageConverter protobufHttpMessageConverter) {

        final RestTemplate restTemplate = new RestTemplate();
        restTemplate.getMessageConverters().add(protobufHttpMessageConverter);
        final MappingJackson2HttpMessageConverter jsonMessageConverter = new MappingJackson2HttpMessageConverter();
        final ObjectMapper objectMapper = new ObjectMapper();
        objectMapper.configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false);
        jsonMessageConverter.setObjectMapper(objectMapper);
        restTemplate.getMessageConverters().add(jsonMessageConverter);
        restTemplate.setRequestFactory(new HttpComponentsClientHttpRequestFactory());
        return restTemplate;
    }

    @Bean
    public ProtobufHttpMessageConverter protobufHttpMessageConverter() {
        return new ProtobufHttpMessageConverter();
    }

I still get the error. I did open a PR to just not always show the error:

0c3c072

I just think having

if (logger.isDebugEnabled()) {
    logger.warn()
} else {
    logger.warn()
}

in the canRead() and canWrite() methods is strange.

[spring-projects-issues]

Juergen Hoeller commented

We're using such an isDebugEnabled check in a few places, deciding whether to log the full stacktrace versus just the exception message in the same line. Essentially, we still want to log at warn level there, just with more context provided. The less user-friendly alternative would be to log regularly at warn level and once again with stacktrace at debug level...

As for the need to log at warn level to begin with, the problem here is that Jackson itself may fail to introspect a Jackson-targeted class. If this remains unnoticed, message conversion simply doesn't happen using Jackson and there is no indication why, just a "no message converter found" exception eventually. Debug level is too low in such a scenario.

Have you tried replacing the list through setMessageConverters or through the corresponding RestTemplate constructor? If you add to the getMessageConverters result, the default converters (including the Jackson one) still remain in place at their original position. You could also simply clear() the getMessageConverters list before adding to it.

[spring-projects-issues]

Claes Mogren commented

Ok, thanks a lot for the help with this. I tried restTemplate.getMessageConverters().clear() but that did not help. Removing the protobuf converter completely gives:

Caused by: org.springframework.web.client.RestClientException: Could not extract response: no suitable HttpMessageConverter found for response type [class com.company.product.component.protobuf.Client$Configurations] and content type [application/json;charset=UTF-8]

Which is also correct, the error is that we take a json, and serialize it directly into a protobuf class.

Then I tried creating a list and using restTemplate.setMessageConverters(list) and again the same error:

2016-04-13 15:48:02.871 WARN [app-service] 17774 --- [AppClient-1] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]

I guess I might have to create a complete testcase for this. What app does is that it has a REST endpoint that returns a protobuf with some configuration, that comes from another service as JSON. So what the app does is basically

return restTemplate.exchange(url, HttpMethod.GET, entity, clazz).getBody();

where clazz is the protobuf generated class. It works fine, just annoying to fill the logs. Is the problem that we use the MappingJackson2HttpMessageConverter for reading and ProtobufHttpMessageConverter for writing in the same exchange?

[spring-projects-issues]

Claes Mogren commented

I closed the PR since it was not the correct way to solve it. But, as far as I could see, the other MessageConverters don't log every time they can't read or write, only if they try and fail to read.

[spring-projects-issues]

Juergen Hoeller commented

Ideally, we'd be able to differentiate between a Jackson exception indicating "this looks like a Jackson-mapped class but has invalid metadata" versus "this doesn't look like a Jackson-intended mapping at all", adapting the log level accordingly.

What does the stacktrace of your JsonMappingException look like? You could switch to debug log level to copy-paste it from there :-)

[spring-projects-issues]

Juergen Hoeller commented

Actually, reviewing the code, there's one thing we can do in any case: Check the media type first before delegating to Jackson for evaluating the given type, i.e. call canRead(mediaType) / canWrite(mediaType) and back out immediately if they return false. That seems like a worthwhile optimization in any scenario, and I guess it might also help on your end?

[spring-projects-issues]

Claes Mogren commented

Debug log:

2016-04-13 21:02:09.881 DEBUG [app-service,643d7b51-fd49-47ef-8dcf-d13c2f5a1cd2] 18440 --- [tp1655627208-17] o.s.web.servlet.DispatcherServlet : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/configurations]
2016-04-13 21:02:09.884 DEBUG [app-service,643d7b51-fd49-47ef-8dcf-d13c2f5a1cd2] 18440 --- [tp1655627208-17] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /configurations
2016-04-13 21:02:09.885 DEBUG [app-service,643d7b51-fd49-47ef-8dcf-d13c2f5a1cd2] 18440 --- [tp1655627208-17] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public com.company.product.component.protobuf.Client$Configurations com.company.product.component.endpoint.ConfigurationController.getAllConfigurations(com.company.product.middleware.common.ClientDevice)]
2016-04-13 21:02:09.885 DEBUG [app-service,643d7b51-fd49-47ef-8dcf-d13c2f5a1cd2] 18440 --- [tp1655627208-17] o.s.web.servlet.DispatcherServlet : Last-Modified value for [/configurations] is: -1
2016-04-13 21:02:09.896 DEBUG [app-service,] 18440 --- [appClient-3] o.s.web.client.RestTemplate : Created GET request for "http://app-api.cloud.com/session"
2016-04-13 21:02:09.899 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:09.900 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:09.900 DEBUG [app-service,] 18440 --- [appClient-3] o.s.web.client.RestTemplate : Setting request Accept header to [application/x-protobuf, text/plain, application/xml, application/json]
2016-04-13 21:02:10.155 DEBUG [app-service,] 18440 --- [appClient-3] o.s.web.client.RestTemplate : GET request for "http://app-api.cloud.company.com/metadata?sessionKey=bdf552915db15698ccd6719ee33b3b86e0347994" resulted in 200 (OK)
2016-04-13 21:02:10.157 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:10.158 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:10.160 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:10.161 WARN [app-service,] 18440 --- [appClient-3] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.component.protobuf.Client$Configurations]: com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
2016-04-13 21:02:10.161 DEBUG [app-service,] 18440 --- [appClient-3] o.s.web.client.RestTemplate : Reading [com.company.product.component.protobuf.Client$Configurations] as "application/json;charset=UTF-8" using [org.springframework.http.converter.protobuf.ProtobufHttpMessageConverter@935493d]
2016-04-13 21:02:10.178 DEBUG [app-service,643d7b51-fd49-47ef-8dcf-d13c2f5a1cd2] 18440 --- [tp1655627208-17] m.m.a.RequestResponseBodyMethodProcessor : Written [....

And yes, backing out immediately sounds like it would help.

[spring-projects-issues]

Juergen Hoeller commented

Alright, the immediate backing out if the media type doesn't match is already available in the latest 4.3.0.BUILD-SNAPSHOT and 4.2.6.BUILD-SNAPSHOT... Feel free to give it a try there!

The JsonMappingException itself unfortunately isn't very distinctive: It's the same exception type, with no clearly differentiating attributes either, for different failure scenarios. So if the rearrangement above doesn't help, I'd rather introduce a dedicated flag.

[spring-projects-issues]

Claes Mogren commented

Thanks, I'm afraid the flag is the way to go. Running with the debug-flag correctly set this time, I still get the Warning in the logs:

2016-04-14 09:57:55.073 WARN [app-service,] 20214 --- [appClient-4] .c.j.MappingJackson2HttpMessageConverter : Failed to evaluate deserialization for type [simple type, class com.company.product.middleware.app.App$Configurations]

com.fasterxml.jackson.databind.JsonMappingException: Can not find a (Map) Key deserializer for type [simple type, class com.google.protobuf.Descriptors$FieldDescriptor]
at com.fasterxml.jackson.databind.deser.DeserializerCache._handleUnknownKeyDeserializer(DeserializerCache.java:604) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.DeserializerCache.findKeyDeserializer(DeserializerCache.java:168) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.DeserializationContext.findKeyDeserializer(DeserializationContext.java:484) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.std.MapDeserializer.createContextual(MapDeserializer.java:231) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.DeserializationContext.handleSecondaryContextualization(DeserializationContext.java:669) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.DeserializationContext.findContextualValueDeserializer(DeserializationContext.java:430) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.std.StdDeserializer.findDeserializer(StdDeserializer.java:947) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.resolve(BeanDeserializerBase.java:439) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCache2(DeserializerCache.java:296) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCacheValueDeserializer(DeserializerCache.java:244) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.deser.DeserializerCache.hasValueDeserializerFor(DeserializerCache.java:191) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.DeserializationContext.hasValueDeserializerFor(DeserializationContext.java:406) ~[jackson-databind-2.6.4.jar:2.6.4]
at com.fasterxml.jackson.databind.ObjectMapper.canDeserialize(ObjectMapper.java:2593) ~[jackson-databind-2.6.4.jar:2.6.4]
at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.canRead(AbstractJackson2HttpMessageConverter.java:153) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.canRead(AbstractJackson2HttpMessageConverter.java:140) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate$AcceptHeaderRequestCallback.doWithRequest(RestTemplate.java:706) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate$HttpEntityRequestCallback.doWithRequest(RestTemplate.java:769) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:594) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:557) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:475) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.web.client.RestTemplate$$FastClassBySpringCGLIB$$aa4e9ed0.invoke(<generated>) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) [spring-core-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.cloud.netflix.metrics.RestTemplateUrlTemplateCapturingAspect.captureUrlTemplate(RestTemplateUrlTemplateCapturingAspect.java:33) [spring-cloud-netflix-core-1.1.0.RC1.jar:1.1.0.RC1]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:620) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:609) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:68) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
at org.springframework.web.client.RestTemplate$$EnhancerBySpringCGLIB$$d8c2497e.exchange(<generated>) [spring-web-4.2.6.BUILD-SNAPSHOT.jar:4.2.6.BUILD-SNAPSHOT]
at com.company.product.middleware.app.appClient.doRequest(appClient.java:155) [main/:na]
at com.company.product.middleware.app.appClient.metadata(appClient.java:88) [main/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72]
at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.execute(MethodExecutionAction.java:116) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.executeWithArgs(MethodExecutionAction.java:93) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.execute(MethodExecutionAction.java:78) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.contrib.javanica.command.GenericCommand$1.execute(GenericCommand.java:47) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.contrib.javanica.command.AbstractHystrixCommand.process(AbstractHystrixCommand.java:146) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.contrib.javanica.command.GenericCommand.run(GenericCommand.java:44) [hystrix-javanica-1.5.1.jar:1.5.1]
at com.netflix.hystrix.HystrixCommand$1.call(HystrixCommand.java:293) [hystrix-core-1.5.1.jar:1.5.1]
at com.netflix.hystrix.HystrixCommand$1.call(HystrixCommand.java:288) [hystrix-core-1.5.1.jar:1.5.1]
at rx.Observable$2.call(Observable.java:162) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable$2.call(Observable.java:154) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable$2.call(Observable.java:162) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable$2.call(Observable.java:154) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable$2.call(Observable.java:162) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable$2.call(Observable.java:154) [rxjava-1.0.14.jar:1.0.14]
at rx.Observable.unsafeSubscribe(Observable.java:7710) [rxjava-1.0.14.jar:1.0.14]
at com.netflix.hystrix.AbstractCommand$5.call(AbstractCommand.java:521) [hystrix-core-1.5.1.jar:1.5.1]
at com.netflix.hystrix.AbstractCommand$5.call(AbstractCommand.java:497) [hystrix-core-1.5.1.jar:1.5.1]
at rx.Observable.unsafeSubscribe(Observable.java:7710) [rxjava-1.0.14.jar:1.0.14]
at rx.internal.operators.OperatorSubscribeOn$1$1.call(OperatorSubscribeOn.java:62) [rxjava-1.0.14.jar:1.0.14]
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:56) [hystrix-core-1.5.1.jar:1.5.1]
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:47) [hystrix-core-1.5.1.jar:1.5.1]
at com.company.pct.request.correlation.hystrix.CorrelatingHystrixConcurrencyStrategy$HystrixCorrelationCallable.call(CorrelatingHystrixConcurrencyStrategy.java:96) [spring-request-correlation-starter-1.0.3-SNAPSHOT.jar:na]
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction.call(HystrixContexSchedulerAction.java:69) [hystrix-core-1.5.1.jar:1.5.1]
at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) [rxjava-1.0.14.jar:1.0.14]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_72]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_72]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72]

Debugging I can see the following values for the parameters:

type: class com.company.product.middleware.app.App$Configuration 
contextClass: null 
mediaType: null
javaType: "[simple type class com.company.product.middleware.app.App$Configuration]"

I could also see that this.objectMapper.canSerialize(clazz, causeRef) in canWrite() works fine and returns true.

[spring-projects-issues]

Claes Mogren commented

By reading the code in HttpMessageConverterExtractor.extractData() where canRead() is called on line 90, I still don't think it should log a Warning when it can't read. That loop throws the correct error later on if no converter could handle the input.

[spring-projects-issues]

Juergen Hoeller commented

In normal operations, Jackson doesn't expose an exception there, so we're not actually logging anything anyway. It's just that for nested value scenarios, Jackson seems to go into a code path where it forgets that it was originally just asked whether it can handle a particular type and suddently throws hard exceptions: Compare com.fasterxml.jackson.databind.deser.DeserializerCache's hasValueDeserializerFor versus findValueDeserializer... When traversing into nested types, it forgets that it was triggered by has* and handles the nested types via find*, throwing an exception in case of no deserializer found.

So to be clear, the only reason why we do warn logging at all there is to handle scenarios where Jackson would otherwise just return false and not expose a mapping problem for a Jackson-mapped type to us. We do not intend to log about types unknown to Jackson there, and usually that works fine, except for types with nested values... like in your scenario. So we need to find a way to ignore such nested no-deserializer-found exceptions. Since Jackson doesn't use specific exception types there, the best we can do seems to be to catch JsonMappingException and check for getMessage().startsWith("Can not find")... seriously :-(

[spring-projects-issues]

Juergen Hoeller commented

I've added explicit introspection of the JsonMappingException now, currently literally checking for a "Can not find" exception message until Jackson provides a distinct subtype here (or fixes its internal inconsistencies in has vs find). This is only in 4.3 through, not in 4.2.6; for the latter, we'll leave it at consistent media type checks upfront (which is not only a worthwhile general optimization but also helps with too much warn logging in related scenarios; see the comments in #15886).

[spring-projects-issues]

Claes Mogren commented

Thanks a lot for the fix! We'll move over to 4.3 as soon as it's ready.

[spring-projects-issues]

Juergen Hoeller commented

It'd be great if you could give the latest 4.3.0.BUILD-SNAPSHOT a try and not only verify that the fix actually works for you but also that there are no other regressions for you in 4.3 :-)

Beyond snapshots, there will be a 4.3 RC2 release on April 28th, as a more definitive state to test against.