New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ConcurrentModificationException at com.consol.citrus.message.DefaultMessage.toString() #302

Closed
ghost opened this Issue Nov 2, 2017 · 7 comments

Comments

Projects
None yet
1 participant
@ghost

ghost commented Nov 2, 2017

While using Citrus (2.7.2) to mock multiple http services and using a a forked http-client, I am facing random exceptions of the following kind:

2017-10-30 16:50:54,246 main [DEBUG ] citrus.util.FileUtils - Reading file resource: 'authentication-response.xml' (encoding is 'UTF-8')
2017-10-30 16:50:54,247 main [INFO  ] consol.citrus.Citrus - 
2017-10-30 16:50:54,247 main [DEBUG ] consol.citrus.Citrus - TEST STEP 3: send
2017-10-30 16:50:54,247 main [DEBUG ] message.correlation.PollingCorrelationManager - Get correlation key for 'citrus_message_correlator_fooMockServer:consumer'
2017-10-30 16:50:54,247 main [DEBUG ] message.correlation.DefaultCorrelationManager - Finding correlated object for 'citrus_message_id = 'db5cd5ba-0ec8-49ed-a6c6-e8c4ff6ac147''
2017-10-30 16:50:54,247 main [DEBUG ] citrus.channel.ChannelSyncConsumer - Sending message to reply channel: 'org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@489da1cc'
2017-10-30 16:50:54,247 main [DEBUG ] citrus.channel.ChannelSyncConsumer - Message to send is:
HTTPMESSAGE [payload: ][headers: {citrus_message_id=081cbc85-84b0-4ef3-89a8-b6039f5bfeef, citrus_message_timestamp=1509378654246, citrus_http_status_code=200, citrus_http_reason_phrase=OK, Content-Type=application/xml}]
2017-10-30 16:50:54,247 main [WARN  ] messaging.core.GenericMessagingTemplate$TemporaryReplyChannel - Reply message received but the receiving thread has exited due to an exception while sending the request message:GenericMessage [payload=HTTPMESSAGE [payload: ][headers: {citrus_message_id=081cbc85-84b0-4ef3-89a8-b6039f5bfeef, citrus_message_timestamp=1509378654246, citrus_http_status_code=200, citrus_http_reason_phrase=OK, Content-Type=application/xml}], headers={id=425b67e2-c350-4329-b57e-12a6dea3772b, timestamp=1509378654247}]
2017-10-30 16:50:54,247 main [INFO  ] citrus.channel.ChannelSyncConsumer - Message was sent to reply channel: 'org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@489da1cc'
2017-10-30 16:50:54,247 main [INFO  ] consol.citrus.Citrus - 
2017-10-30 16:50:54,247 main [DEBUG ] consol.citrus.Citrus - TEST STEP 3 SUCCESS
2017-10-30 16:50:54,248 main [INFO  ] consol.citrus.Citrus - 
2017-10-30 16:50:54,248 main [DEBUG ] consol.citrus.Citrus - TEST STEP 4: receive
2017-10-30 16:50:54,248 main [DEBUG ] citrus.channel.ChannelConsumer - Receiving message from: fooMockServer.inbound
2017-10-30 16:50:54,246 qtp1242427797-27 [DEBUG ] http.servlet.CitrusDispatcherServlet - Could not complete request
org.springframework.messaging.MessageDeliveryException: failed to send Message to channel 'fooMockServer.inbound'; nested exception is java.util.ConcurrentModificationException
	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:451) ~[spring-integration-core-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:375) ~[spring-integration-core-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.messaging.core.GenericMessagingTemplate.doSend(GenericMessagingTemplate.java:115) ~[spring-messaging-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.messaging.core.GenericMessagingTemplate.doSendAndReceive(GenericMessagingTemplate.java:150) ~[spring-messaging-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.messaging.core.GenericMessagingTemplate.doSendAndReceive(GenericMessagingTemplate.java:45) ~[spring-messaging-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.messaging.core.AbstractMessagingTemplate.sendAndReceive(AbstractMessagingTemplate.java:42) ~[spring-messaging-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.integration.core.MessagingTemplate.sendAndReceive(MessagingTemplate.java:97) ~[spring-integration-core-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at com.consol.citrus.channel.ChannelSyncProducer.send(ChannelSyncProducer.java:76) ~[citrus-core-2.7.2.jar:?]
	at com.consol.citrus.channel.ChannelEndpointAdapter.handleMessageInternal(ChannelEndpointAdapter.java:68) ~[citrus-core-2.7.2.jar:?]
	at com.consol.citrus.endpoint.AbstractEndpointAdapter.handleMessage(AbstractEndpointAdapter.java:55) ~[citrus-core-2.7.2.jar:?]
	at com.consol.citrus.http.controller.HttpMessageController.handleRequestInternal(HttpMessageController.java:150) ~[citrus-http-2.7.2.jar:?]
	at com.consol.citrus.http.controller.HttpMessageController.handlePostRequest(HttpMessageController.java:63) ~[citrus-http-2.7.2.jar:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_131]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_131]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_131]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_131]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133) ~[spring-web-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) ~[spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) [spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) [spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) [javax.servlet-api-3.1.0.jar:3.1.0]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) [spring-webmvc-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api-3.1.0.jar:3.1.0]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at com.consol.citrus.http.servlet.GzipServletFilter.doFilterInternal(GzipServletFilter.java:43) [citrus-http-2.7.2.jar:?]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at com.consol.citrus.http.servlet.RequestCachingServletFilter.doFilterInternal(RequestCachingServletFilter.java:41) [citrus-http-2.7.2.jar:?]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524) [jetty-security-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) [jetty-servlet-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:219) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.Server.handle(Server.java:561) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [jetty-server-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) [jetty-io-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104) [jetty-io-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) [jetty-io-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597) [jetty-util-9.4.7.v20170914.jar:9.4.7.v20170914]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
Caused by: java.util.ConcurrentModificationException
	at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437) ~[?:1.8.0_131]
	at java.util.HashMap$EntryIterator.next(HashMap.java:1471) ~[?:1.8.0_131]
	at java.util.HashMap$EntryIterator.next(HashMap.java:1469) ~[?:1.8.0_131]
	at java.util.AbstractMap.toString(AbstractMap.java:554) ~[?:1.8.0_131]
	at java.lang.String.valueOf(String.java:2994) ~[?:1.8.0_131]
	at java.lang.StringBuilder.append(StringBuilder.java:131) ~[?:1.8.0_131]
	at com.consol.citrus.message.DefaultMessage.toString(DefaultMessage.java:108) ~[citrus-core-2.7.2.jar:?]
	at java.lang.String.valueOf(String.java:2994) ~[?:1.8.0_131]
	at java.lang.StringBuilder.append(StringBuilder.java:131) ~[?:1.8.0_131]
	at org.springframework.messaging.support.GenericMessage.toString(GenericMessage.java:111) ~[spring-messaging-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	at java.lang.String.valueOf(String.java:2994) ~[?:1.8.0_131]
	at java.lang.StringBuilder.append(StringBuilder.java:131) ~[?:1.8.0_131]
	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:432) ~[spring-integration-core-4.3.12.RELEASE.jar:4.3.12.RELEASE]
	... 63 more

I created a demo project that (after running it a couple of times) duplicates the behavior.

@ghost

This comment has been minimized.

ghost commented Nov 2, 2017

It seems that the exception occurs when printing the headers of a DefaultMessage, which iterates over a HashMap. I don't know why the headers are changed and if this behavior is correct, but a workaround would be to either use a (thread-safe) copy of the headers or use a ConcurentHashMap when calling toString().

@christophd christophd added this to the v2.7.3 milestone Nov 2, 2017

@christophd

This comment has been minimized.

Member

christophd commented Nov 3, 2017

I was not able to reproduce this behavior on MacOS with Java 8. I need to find a way to execute this on Windows 10. Coming back to you then.

@ghost

This comment has been minimized.

ghost commented Nov 3, 2017

This is not limited to Windows. The issue also occurs on RHEL 6.9 with JDK 1.8.0_121.

@ghost

This comment has been minimized.

ghost commented Nov 6, 2017

You are correct. The test does not work. I'll try to provide a working one.

@ghost

This comment has been minimized.

ghost commented Nov 8, 2017

I updated the test and was able to reproduce the error. Please try again, using the foo.sh script.

@christophd christophd removed the READY label Nov 13, 2017

christophd added a commit that referenced this issue Nov 13, 2017

@christophd

This comment has been minimized.

Member

christophd commented Nov 13, 2017

Thanks for the sample project that made it easy to reproduce. My first thought was that default message toString() is not thread safe. Then I was convinced that the internal message header list object instance is the root cause of the problem.

Turned out that it is the Spring integration message channel that is internally used in server components. The channel has a debug logging feature that prints out the messages preSend and postSend. The postSend logging operation crashes when the consumer reads the message from the channel at the same time.

So it is related to debug logging enabled in logging framework and on the message channel. If you disable the debug logging on that channel the problem is fixed. This is also why I had hard times to reproduce as logging level is not always set to debug.

Also I changed the channel logging to disabled by default in Citrus 2.7.3. Up to then you can change the logging level for the message channel logging as follows:

<logger name="com.consol.citrus.channel.MessageSelectingQueueChannel">
  <level value="INFO"/>
</logger>
@ghost

This comment has been minimized.

ghost commented Nov 14, 2017

Thanks for the quick fix and the detailed description of the issue! I'll adjust my logging settings accordingly until 2.7.3 is available.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment