StructuredArguments.value fails to escape the String serialization of an Object. Causes Elasticsearch to reject forwarded event from Logstash agent.
For some Apps this is working just fine. In others with identical dependencies to those below and with & identical logback-spring.xml the encoder somehow doesn't work properly.
Several demo variations are ready to examine. Just checkout the named git branch.
| Branch | Spring Boot | Logback Logstash Encoder | Jackson | Logback | Notes |
|---|---|---|---|---|---|
| master & sb15lle4 | 1.5.16 | 4.11 | 2.8.11 | 1.1.11 | Mysteriously works in some apps and not others. Doesn't work in this demo. |
| sb15lle5 | 1.5.16 | 5.2 | 2.8.11 | 1.1.11 | |
| sb21lle4 | 2.1.2 | 4.11 | 2.9.8 | 1.2.3 | |
| sb21lle5 | 2.1.2 | 5.2 | 2.9.8 | 1.2.3 |
Checkout a branch
run ./gradlew check
See console output
// value("report-request-body", reportMessageDTO) ** FAIL **
{"@timestamp":"2019-01-17T16:17:07.326+00:00","@version":1,"report-id":1,"report-request-body":{"id":1,"createdOn":"2018-07-19 05:33:48","startDate":"2018-11-05","endDate":"2018-11-05","reportName":"Report for simple data","reportPropertiesVersion":"2.0","reportProperties":{"prop1":"value1","prop2":"value2"},"limit":null},"severity":"INFO","service":"logstash-logback-encoder-bug","trace":"8d32cc5847e1ba8d","span":"8d32cc5847e1ba8d","parent":"","exportable":"false","pid":"45659","thread":"Test worker","class":"c.i.nemo.controllers.SampleController","message":"Report report-id=1 requested.","env-profiles":"test","host":"localhost"}
// Logstash agent log from something else similar
[2019-01-04T18:14:53,614][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"SOME_INDEX", :_type=>"app", :_routing=>nil}, 2019-01-04T23:14:52.796Z localhost Report report-id=1 requested], :response=>{"index"=>{"_index"=>"INDEX_NAME", "_type"=>"app", "_id"=>"AWgbJd__DXl-JdQiLMhX", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse [report-request-body]", "caused_by"=>{"type"=>"illegal_state_exception", "reason"=>"Can't get text on a START_OBJECT at 1:496"}}}}}
Seems as though a nested JSON property must be represented as an escaped String to be accepted by Elasticsearch
Good Event: {"prop1": "val1", "nested": "{\"nestedProp1\":5}"}
Bad Event: {"prop1": "val1", "nested": {"nestedProp1":5}}
Again, in some Apps this is happening correctly. In others not.
// value("report-request-body", objectMapper.writeValueAsString(reportMessageDTO) WORKS
{"@timestamp":"2019-01-17T16:17:07.346+00:00","@version":1,"report-request-body":"{\"id\":1,\"createdOn\":\"2018-07-19 05:33:48\",\"startDate\":\"2018-11-05\",\"endDate\":\"2018-11-05\",\"reportName\":\"Report for simple data\",\"reportPropertiesVersion\":\"2.0\",\"reportProperties\":{\"prop1\":\"value1\",\"prop2\":\"value2\"},\"limit\":null}","severity":"INFO","service":"logstash-logback-encoder-bug","trace":"8d32cc5847e1ba8d","span":"8d32cc5847e1ba8d","parent":"","exportable":"false","pid":"45659","thread":"Test worker","class":"c.i.nemo.controllers.SampleController","message":"Forced JSON serialization","env-profiles":"test","host":"localhost"}
// kv("escape-this", "Did \"THIS\" get escaped?") WORKS
{"@timestamp":"2019-01-17T16:17:07.346+00:00","@version":1,"escape-this":"Did \"THIS\" get escaped?","severity":"INFO","service":"logstash-logback-encoder-bug","trace":"8d32cc5847e1ba8d","span":"8d32cc5847e1ba8d","parent":"","exportable":"false","pid":"45659","thread":"Test worker","class":"c.i.nemo.controllers.SampleController","message":"Escape test 1 escape-this=Did \"THIS\" get escaped?","env-profiles":"test","host":"localhost"}
// logger.error("Triggered exception", new RuntimeException("This String \"NEEDS\" \"escaping\"")); WORKS
{"@timestamp":"2019-01-17T16:17:07.406+00:00","@version":1,"stack_trace":"java.lang.RuntimeException: This String \"NEEDS\" \"escaping\"\n\tat com.integralads.nemo.controllers.SampleController.triggerException(SampleController.java:49)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:497)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)\n\tat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:849)\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:760)\n\tat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)\n\tat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)\n\tat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)\n\tat org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)\n\tat org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:635)\n\tat org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)\n\tat org.springframework.test.web.servlet.TestDispatcherServlet.service(TestDispatcherServlet.java:71)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:742)\n\tat org.springframework.mock.web.MockFilterChain$ServletFilterProxy.doFilter(MockFilterChain.java:160)\n\tat org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:127)\n\tat org.springframework.test.web.servlet.MockMvc.perform(MockMvc.java:151)\n\tat org.springframework.test.web.servlet.MockMvc$perform.call(Unknown Source)\n\tat org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)\n\tat org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)\n\tat org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:128)\n\tat com.integralads.nemo.controllers.BaseControllerTest.doGet(BaseControllerTest.groovy:43)\n\tat com.integralads.nemo.controllers.BaseControllerTest$doGet$0.callCurrent(Unknown Source)\n\tat org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:51)\n\tat org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:157)\n\tat org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)\n\tat com.integralads.nemo.controllers.SampleControllerIntegrationTest.$spock_feature_1_1(SampleControllerIntegrationTest.groovy:30)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:497)\n\tat org.spockframework.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:188)\n\tat org.spockframework.runtime.model.MethodInfo.invoke(MethodInfo.java:84)\n\tat org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)\n\tat org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)\n\tat org.spockframework.runtime.BaseSpecRunner.runFeatureMethod(BaseSpecRunner.java:406)\n\tat org.spockframework.runtime.BaseSpecRunner.doRunIteration(BaseSpecRunner.java:324)\n\tat org.spockframework.runtime.BaseSpecRunner$6.invoke(BaseSpecRunner.java:309)\n\tat org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)\n\tat org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)\n\tat org.spockframework.runtime.BaseSpecRunner.runIteration(BaseSpecRunner.java:288)\n\tat org.spockframework.runtime.BaseSpecRunner.initializeAndRunIteration(BaseSpecRunner.java:278)\n\tat org.spockframework.runtime.BaseSpecRunner.runSimpleFeature(BaseSpecRunner.java:269)\n\tat org.spockframework.runtime.BaseSpecRunner.doRunFeature(BaseSpecRunner.java:263)\n\tat org.spockframework.runtime.BaseSpecRunner$5.invoke(BaseSpecRunner.java:246)\n\tat org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)\n\tat org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)\n\tat org.spockframework.runtime.BaseSpecRunner.runFeature(BaseSpecRunner.java:238)\n\tat org.spockframework.runtime.BaseSpecRunner.runFeatures(BaseSpecRunner.java:188)\n\tat org.spockframework.runtime.BaseSpecRunner.doRunSpec(BaseSpecRunner.java:98)\n\tat org.spockframework.runtime.BaseSpecRunner$1.invoke(BaseSpecRunner.java:84)\n\tat org.spockframework.runtime.BaseSpecRunner.invokeRaw(BaseSpecRunner.java:481)\n\tat org.spockframework.runtime.BaseSpecRunner.invoke(BaseSpecRunner.java:464)\n\tat org.spockframework.runtime.BaseSpecRunner.runSpec(BaseSpecRunner.java:76)\n\tat org.spockframework.runtime.BaseSpecRunner.run(BaseSpecRunner.java:67)\n\tat org.spockframework.runtime.Sputnik.run(Sputnik.java:63)\n\tat org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:106)\n\tat org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)\n\tat org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)\n\tat org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:66)\n\tat org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:497)\n\tat org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)\n\tat org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)\n\tat org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)\n\tat org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)\n\tat com.sun.proxy.$Proxy2.processTestClass(Unknown Source)\n\tat org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:117)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:497)\n\tat org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)\n\tat org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)\n\tat org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:155)\n\tat org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:137)\n\tat org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)\n\tat org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)\n\tat org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)\n\tat java.lang.Thread.run(Thread.java:745)\n","severity":"ERROR","service":"logstash-logback-encoder-bug","trace":"2f7958d5e1ff2a9d","span":"2f7958d5e1ff2a9d","parent":"","exportable":"false","pid":"45659","thread":"Test worker","class":"c.i.nemo.controllers.SampleController","message":"Triggered exception","env-profiles":"test","host":"localhost"}