Handler gets invoked twice from publisher

[SimonT]

I am currently testing Spring Integration 1.0.0.M5 and I have run in an unexplained behavior. I created a simple Echo test case.

I defined a Publisher which publish a String on a channel (A). A Handler listens to the channel (A) an reads the String and echoes the reponse back onto another channel (B). The String published on channel (B) gets read and validated by a Subscriber.

What is weird is that my handler method gets invoked twice and I have no clue as to why? But my Subscriber only reads one answer from channel B, which is ok.

How come the handler gets invoked twice when it gets called from a publisher? Is this a bug?

I have included my demo source code as an attachment. Look for test case.
EchoStringClientServerTest.java


Thanks for your help,

Simon

[iwein]

I had a look at your code. Thanks for the TestCase! There should be something similar in the testsuite for the project.

I don't have more time to go into it now, but if the behavior is as you say it could very well be a bug.

[SimonT]

I have updated my test cases with some more and found that the handler gets invoked twice which is pretty annoying (Bug).

Also, it looks like it is impossible to retrieve a Message<T> from a Subscriber due to a classCastException. Basically, it seems like the Subscriber can only deal with the payload of a message but not the message itself (see EchoMessageStringClientServerTest.java). The subscriber annotation should allow for Message<T> since without it we cannot do any sort of message correlation since we don't have a hold on the message.

I have included my test cases with this post.


Simon.

[Mark Fisher]

Simon,

Thanks for the code and explanation. We now have an open issue for this (thanks Iwein): http://jira.springframework.org/browse/INT-299

You are referring to the @Handler method that is invoked twice? or do just see two invocations of the endpoint? (the poller also invokes the endpoint). Do you see the same thing if you change the request channel to a <direct-channel/> ?

-Mark

[iwein]

I ran the tests. In my case, the message is handled only once with both the default and direct-channel. See this test:

	@Test
	public void testEchoClientServer() throws InterruptedException
	{
		CountDownLatch latch = new CountDownLatch(4);
		echoClient.setLatch(latch);
		echoClient.publishRequest("myPayload");
		latch.await(3, TimeUnit.SECONDS);
	}

Note that I increased the latch to see if any more handler invocations would happen. It just times out and everything is ok:

EchoStringClientService: Publishing payload: myPayload
EchoStringClientService: Handling reply payload: myPayload

[SimonT]

Have you changed anything to the ApplicationContext.xml?

How many System.err.println("Echo") message do you see printed out in the log by the EchoStringServerService.java class? I see 2 "echo" printout, thus what I believe is the bug...

Here's my log:

...

2008-07-14@09:07:52 DEBUG [main] (ProfileValueUtils.java:63) Retrieved @ProfileValueSourceConfiguration [null] for test class [messagingservices.EchoStringClientServerTest]
2008-07-14@09:07:52 DEBUG [main] (ProfileValueUtils.java:75) Retrieved ProfileValueSource type [class org.springframework.test.annotation.SystemProfileV alueSource] for class [messagingservices.EchoStringClientServerTest]
2008-07-14@09:07:52 DEBUG [main] (EchoStringClientService.java:34) Publishing payload: myPayload
2008-07-14@09:07:52 DEBUG [message-bus-1] (AbstractEndpoint.java:246) endpoint 'echoStringClientService-handleReply-endpoint' handling message: [ID=316a5a09-1276-46de-93bc-2626473d0ffd][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='org.springframework.integration.endpoint. EndpointPoller@737371']
2008-07-14@09:07:52 DEBUG [message-bus-2] (AbstractEndpoint.java:246) endpoint 'messagingservices.EchoStringServerService#0.Messa geHandler.endpoint' handling message: [ID=545de4fe-deb2-4644-9c92-f1f449abad9c][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='org.springframework.integration.endpoint. EndpointPoller@1e328e0']
2008-07-14@09:07:52 DEBUG [main] (AbstractMessageChannel.java:199) preSend on channel 'testRequestChannel', message: [ID=9572698d-e1cd-4811-88b1-21d96e9195f0][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [main] (AbstractMessageChannel.java:211) postSend (sent=true) on channel 'testRequestChannel', message: [ID=9572698d-e1cd-4811-88b1-21d96e9195f0][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [message-bus-2] (AbstractMessageChannel.java:232) postReceive on channel 'testRequestChannel', message: [ID=9572698d-e1cd-4811-88b1-21d96e9195f0][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 TRACE [message-bus-2] (EchoStringServerService.java:18) Echo
2008-07-14@09:07:52 TRACE [message-bus-2] (EchoStringServerService.java:18) Echo
2008-07-14@09:07:52 DEBUG [message-bus-2] (HandlerEndpoint.java:161) endpoint 'messagingservices.EchoStringServerService#0.Messa geHandler.endpoint' replying to channel 'testReplyChannel' with message: [ID=1c07978b-0e90-45fa-af6f-472d8189bbe2][Header=[CorrelationID=9572698d-e1cd-4811-88b1-21d96e9195f0][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [message-bus-2] (AbstractMessageChannel.java:199) preSend on channel 'testReplyChannel', message: [ID=1c07978b-0e90-45fa-af6f-472d8189bbe2][Header=[CorrelationID=9572698d-e1cd-4811-88b1-21d96e9195f0][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [message-bus-2] (AbstractMessageChannel.java:211) postSend (sent=true) on channel 'testReplyChannel', message: [ID=1c07978b-0e90-45fa-af6f-472d8189bbe2][Header=[CorrelationID=9572698d-e1cd-4811-88b1-21d96e9195f0][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [message-bus-1] (AbstractMessageChannel.java:232) postReceive on channel 'testReplyChannel', message: [ID=1c07978b-0e90-45fa-af6f-472d8189bbe2][Header=[CorrelationID=9572698d-e1cd-4811-88b1-21d96e9195f0][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='myPayload']
2008-07-14@09:07:52 DEBUG [message-bus-2] (AbstractEndpoint.java:246) endpoint 'messagingservices.EchoStringServerService#0.Messa geHandler.endpoint' handling message: [ID=643b5dc6-f270-479f-a3d6-64e18a510141][Header=[CorrelationID=null][Properties={}][Attributes={}][Timestamp=Mon Jul 14 09:07:52 EDT 2008][Expiration=null][Priority=NORMAL][Sequence #1 (of 1)]][Payload='org.springframework.integration.endpoint. EndpointPoller@148662']
2008-07-14@09:07:52 DEBUG [message-bus-1] (EchoStringClientService.java:45) Handling reply payload: myPayload
echo
echo
2008-07-14@09:07:52 DEBUG [main] (SpringMethodRoadie.java:256) Test method [public void messagingservices.EchoStringClientServerTest.testE choClientServer() throws java.lang.InterruptedException] threw exception: null

...

[iwein]

I fiddled with it to get it to work, but I don't think I changed anything fundamental. Afain I left the application contexts intact (other than changing the packages since I was moving your code into the Spring Integration test suite).

I have written a simplified version of your testcases that show 4 cases to work:
- publish string, subscribe string
- publish message, subscribe message
- publish string, subscribe message
- publish message, subscribe string

I didn't actually run EchoMessageStringClientServerTest successfully as it gave me a CCE, and when I fixed that I got a NSME, so I decided to do a clean setup for the patch.

You can check out the patch attached to INT-299.