Rhino Queues: Transaction Atomicity Issue

[ColinA]

I'm having a bit of trouble while testing how resilient Rhino Queues is to failures - most likely it is something I am doing wrong or not understanding! Basically, I am intermittently receiving the same message multiple times, even though it has previously been received within a transaction.

Here is the code for a console application that I wrote just to play around:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Text;
using System.Transactions;

using Rhino.Queues;

namespace Test
{
    class Program : IDisposable
    {
        private static QueueManager receiver;
        private static QueueManager sender;

        static void Main(string[] args)
        {
            var receiver = new QueueManager(new IPEndPoint(IPAddress.Loopback, 4545), "receiver.esent");
            receiver.CreateQueues("test");
            receiver.Start();

            var sender = new QueueManager(new IPEndPoint(IPAddress.Loopback, 4546), "sender.esent");
            sender.Start();

            using (var tx = new TransactionScope())
            {
                sender.Send(new Uri("rhino.queues://localhost:4545/test"),
                    new MessagePayload
                    {
                        Data = Encoding.ASCII.GetBytes("Test message")
                    });

                tx.Complete();
            }

            while (true)
            {
                using (var tx = new TransactionScope())
                {
                    try
                    {
                        var msg = receiver.Receive("test", new TimeSpan(0, 0, 5));

                        Console.WriteLine(msg.Id.MessageIdentifier.ToString() + ": " + Encoding.ASCII.GetString(msg.Data));

                        tx.Complete();

                        Console.WriteLine("\tTX complete");
                    }
                    catch (TimeoutException)
                    {
                        Console.WriteLine("\tTimeout");
                        break;
                    }
                }
                Console.WriteLine("\tTX end");
                System.Diagnostics.Process.GetCurrentProcess().Kill();
            }

            Console.WriteLine("Press Enter to exit");
            Console.ReadLine();
        }

        public void Dispose()
        {
            if (sender != null)
                sender.Dispose();

            if (receiver != null)
                receiver.Dispose();
        }
    }
}

First, I run it once, with the System.Diagnostics.Process.GetCurrentProcess().Kill(); uncommented. Next I comment out the System.Diagnostics.Process.GetCurrentProcess().Kill(); and run it again.

So, here is my understanding of what happened on the first run:

1. One message was sent, and was received within a transaction
2. That transaction completed sucessfully
3. The process terminated

And here is my understanding of what should happen on the second run:

1. One message is sent, and will be received within a transaction
2. Thre are no moe messages left to receive, so we will timeout and exit gracefully

However, sometimes on the second run I am receiving both the new message, and the message that I received on the previous run.

Is this the expected behaviour?

Thanks!

Colin

[Corey Kaylor]

Can you turn on DEBUG level logging for log4net and show what the log statements output?

--
You received this message because you are subscribed to the Google Groups "Rhino Tools Dev" group.
To view this discussion on the web visit https://groups.google.com/d/msg/rhino-tools-dev/-/Q4YMdLpCo60J.
To post to this group, send email to rhino-t...@googlegroups.com.
To unsubscribe from this group, send email to rhino-tools-d...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/rhino-tools-dev?hl=en.

[ColinA]

I did that and noticed when I started the 2nd run that the first message was:

Changing message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a status to ReadyToDeliver on test

Here is the full log from the first run, where the process is killed after committing the transaction:

2011-10-26 07:56:08,514 DEBUG Starting to listen on 127.0.0.1:4545
2011-10-26 07:56:09,018 DEBUG Starting to listen on 127.0.0.1:4546
2011-10-26 07:56:09,093 DEBUG Enlisting in the current transaction with enlistment id: c577d4d2-0a54-4d9c-bff0-eb4a5ac898c8
2011-10-26 07:56:09,102 DEBUG Created output message 'f8ea75df-598c-4eaa-9137-9f880082c76a' for 'rhino.queues://localhost:4545/test/' as NotReady
2011-10-26 07:56:09,103 DEBUG Committing enlistment with id: c577d4d2-0a54-4d9c-bff0-eb4a5ac898c8
2011-10-26 07:56:09,107 DEBUG Marking output message -118852129 as Ready
2011-10-26 07:56:09,108 DEBUG Commited enlistment with id: c577d4d2-0a54-4d9c-bff0-eb4a5ac898c8
2011-10-26 07:56:09,109 DEBUG Enlisting in the current transaction with enlistment id: 7c8606c1-6f49-490d-a4dd-e310c91eefca
2011-10-26 07:56:10,035 DEBUG Scanning message f8ea75df-598c-4eaa-9137-9f880082c76a with status Ready to be sent at 10/26/2011 07:56:09
2011-10-26 07:56:10,036 DEBUG Adding message f8ea75df-598c-4eaa-9137-9f880082c76a to returned messages
2011-10-26 07:56:10,042 DEBUG Marking output message f8ea75df-598c-4eaa-9137-9f880082c76a as InFlight
2011-10-26 07:56:11,070 DEBUG Starting to send 1 messages to localhost:4545
2011-10-26 07:56:11,102 DEBUG Scanning message f8ea75df-598c-4eaa-9137-9f880082c76a with status InFlight to be sent at 10/26/2011 07:56:09
2011-10-26 07:56:11,138 DEBUG Accepting connection from 127.0.0.1:50224
2011-10-26 07:56:11,141 DEBUG Successfully connected to localhost:4545
2011-10-26 07:56:11,142 DEBUG Writing length of 70 bytes to localhost:4545
2011-10-26 07:56:11,149 DEBUG Writing 70 bytes to localhost:4545
2011-10-26 07:56:11,151 DEBUG Successfully wrote to localhost:4545
2011-10-26 07:56:11,154 DEBUG Reading 70 bytes from 127.0.0.1:50224
2011-10-26 07:56:11,155 DEBUG Deserialized 1 messages from 127.0.0.1:50224
2011-10-26 07:56:11,163 DEBUG Enqueuing msg to 'test' with subqueue: ''. Id: 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a
2011-10-26 07:56:11,165 DEBUG All messages from 127.0.0.1:50224 were accepted
2011-10-26 07:56:11,165 DEBUG Sending reciept notice to 127.0.0.1:50224
2011-10-26 07:56:11,165 DEBUG Reading acknowledgement about accepting messages to 127.0.0.1:50224
2011-10-26 07:56:11,168 DEBUG Changing message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a status to ReadyToDeliver on test
2011-10-26 07:56:11,172 DEBUG Scanning incoming message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a on 'test/' with status ReadyToDeliver
2011-10-26 07:56:11,172 DEBUG Dequeuing message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a from 'test/'
2011-10-26 07:56:11,173 DEBUG Successfully sent output message -118852129
2011-10-26 07:56:11,187 DEBUG Committing enlistment with id: 7c8606c1-6f49-490d-a4dd-e310c91eefca
2011-10-26 07:56:11,225 DEBUG Moving message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a on queue test to history
2011-10-26 07:56:11,250 DEBUG Commited enlistment with id: 7c8606c1-6f49-490d-a4dd-e310c91eefca

 
And here is the log from the second run:

2011-10-26 07:56:33,652 DEBUG Changing message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a status to ReadyToDeliver on test
2011-10-26 07:56:33,761 DEBUG Starting to listen on 127.0.0.1:4545
2011-10-26 07:56:35,446 DEBUG Starting to listen on 127.0.0.1:4546
2011-10-26 07:56:35,555 DEBUG Enlisting in the current transaction with enlistment id: b126ec27-f08f-4532-a38c-1d1537e3a563
2011-10-26 07:56:35,555 DEBUG Created output message 'b5720e4b-64f2-462e-a488-9f880082e66b' for 'rhino.queues://localhost:4545/test/' as NotReady
2011-10-26 07:56:35,555 DEBUG Committing enlistment with id: b126ec27-f08f-4532-a38c-1d1537e3a563
2011-10-26 07:56:35,555 DEBUG Marking output message -1250816437 as Ready
2011-10-26 07:56:35,571 DEBUG Commited enlistment with id: b126ec27-f08f-4532-a38c-1d1537e3a563
2011-10-26 07:56:35,571 DEBUG Enlisting in the current transaction with enlistment id: 4f8167b4-dfbb-4c21-b406-27c5a3c43699
2011-10-26 07:56:35,586 DEBUG Scanning incoming message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a on 'test/' with status ReadyToDeliver
2011-10-26 07:56:35,586 DEBUG Dequeuing message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a from 'test/'
2011-10-26 07:56:35,617 DEBUG Committing enlistment with id: 4f8167b4-dfbb-4c21-b406-27c5a3c43699
2011-10-26 07:56:35,617 DEBUG Moving message 4b1efc58-dac7-40c9-9157-6193bf77b816/f8ea75df-598c-4eaa-9137-9f880082c76a on queue test to history
2011-10-26 07:56:35,617 DEBUG Commited enlistment with id: 4f8167b4-dfbb-4c21-b406-27c5a3c43699
2011-10-26 07:56:35,617 DEBUG Enlisting in the current transaction with enlistment id: a322be97-bb15-4433-871e-f103c5dcf226
2011-10-26 07:56:36,522 DEBUG Scanning message b5720e4b-64f2-462e-a488-9f880082e66b with status Ready to be sent at 10/26/2011 07:56:35
2011-10-26 07:56:36,522 DEBUG Adding message b5720e4b-64f2-462e-a488-9f880082e66b to returned messages
2011-10-26 07:56:36,522 DEBUG Marking output message b5720e4b-64f2-462e-a488-9f880082e66b as InFlight
2011-10-26 07:56:37,489 DEBUG Starting to send 1 messages to localhost:4545
2011-10-26 07:56:37,505 DEBUG Scanning message b5720e4b-64f2-462e-a488-9f880082e66b with status InFlight to be sent at 10/26/2011 07:56:35
2011-10-26 07:56:37,551 DEBUG Accepting connection from 127.0.0.1:50230
2011-10-26 07:56:37,551 DEBUG Successfully connected to localhost:4545
2011-10-26 07:56:37,551 DEBUG Writing length of 70 bytes to localhost:4545
2011-10-26 07:56:37,551 DEBUG Writing 70 bytes to localhost:4545
2011-10-26 07:56:37,551 DEBUG Successfully wrote to localhost:4545
2011-10-26 07:56:37,567 DEBUG Reading 70 bytes from 127.0.0.1:50230
2011-10-26 07:56:37,567 DEBUG Deserialized 1 messages from 127.0.0.1:50230
2011-10-26 07:56:37,567 DEBUG Enqueuing msg to 'test' with subqueue: ''. Id: 4b1efc58-dac7-40c9-9157-6193bf77b816/b5720e4b-64f2-462e-a488-9f880082e66b
2011-10-26 07:56:37,567 DEBUG All messages from 127.0.0.1:50230 were accepted
2011-10-26 07:56:37,567 DEBUG Sending reciept notice to 127.0.0.1:50230
2011-10-26 07:56:37,567 DEBUG Reading acknowledgement about accepting messages to 127.0.0.1:50230
2011-10-26 07:56:37,567 DEBUG Changing message 4b1efc58-dac7-40c9-9157-6193bf77b816/b5720e4b-64f2-462e-a488-9f880082e66b status to ReadyToDeliver on test
2011-10-26 07:56:37,583 DEBUG Scanning incoming message 4b1efc58-dac7-40c9-9157-6193bf77b816/b5720e4b-64f2-462e-a488-9f880082e66b on 'test/' with status ReadyToDeliver
2011-10-26 07:56:37,583 DEBUG Dequeuing message 4b1efc58-dac7-40c9-9157-6193bf77b816/b5720e4b-64f2-462e-a488-9f880082e66b from 'test/'
2011-10-26 07:56:37,583 DEBUG Committing enlistment with id: a322be97-bb15-4433-871e-f103c5dcf226
2011-10-26 07:56:37,583 DEBUG Moving message 4b1efc58-dac7-40c9-9157-6193bf77b816/b5720e4b-64f2-462e-a488-9f880082e66b on queue test to history
2011-10-26 07:56:37,598 DEBUG Successfully sent output message -1250816437
2011-10-26 07:56:37,614 DEBUG Commited enlistment with id: a322be97-bb15-4433-871e-f103c5dcf226
2011-10-26 07:56:37,614 DEBUG Enlisting in the current transaction with enlistment id: 25923573-76a3-484f-add2-6169276cf353
2011-10-26 07:56:42,668 DEBUG Rolling back enlistment with id: 25923573-76a3-484f-add2-6169276cf353
2011-10-26 07:56:42,668 DEBUG Rolledback enlistment with id: 25923573-76a3-484f-add2-6169276cf353

Thanks for your help with this!

[ColinA]

I've been taking another look at this today, but still can't see why I'm getting the previously sent message re-sent on the subsequent run. As far as I can see from the logs the transaction was commited OK, so there should be no reason for this.

Is this an issue with Rhino Queues?

[nightwatch77]

There are many decent and production ready message queuing mechanisms.
Maybe you should re-think your choice? After all, message queue is all
about making sure your message is delivered exactly once. Did you look
what message are there in the queue/queues?

[ColinA]

Yes, my problem is that in this case the message is not being delivered exactly once, despite the use of transactions.

Are you saying Rhino Queues is not production ready?

[nightwatch77]

Well, I don't know RQ so I can't say if it's production ready or not.
Maybe someone who is using this in production could say something.
But if I were to decide if it's production ready or not I'd look at
- the set of management, monitoring and debugging tools available. Is
there a tool that can help you with this problem? Can you look inside
the queue and see what messages are there?
- documentation, examples, use cases
- support from community
- real-world performance information
RQ is an interesting project and I see it has some advantages over
MSMQ but it's a niche technology as for now so be prepared for some
pioneering if you use it.

Best regards
RG




On 28 Paź, 11:41, ColinA <colin.anderson...@googlemail.com> wrote:
> Yes, my problem is that in this case the message is *not *being delivered

[ColinA]

A little bit more info about the issue.

If I use the LINQPad query from here:
https://groups.google.com/forum/#!topic/rhino-tools-dev/xjYK-ThQ6h8

I see that after the first run the message is still sitting in the 'receiver' queue.

[Corey Kaylor]

I do believe this is a bug. My hunch is that it has to do with the lazy flush settings on esent, but unfortunately I haven't had any time to dig in. This is the busiest time of the year for me. I do think I will have time this afternoon though. Sorry for the delay.

--
You received this message because you are subscribed to the Google Groups "Rhino Tools Dev" group.

To view this discussion on the web visit https://groups.google.com/d/msg/rhino-tools-dev/-/OfOEYD0FQksJ.

[cocowalla]

Hi Corey,

Sorry to nag :)

I was wondering if you'd had a chance to look into this yet?

[Corey Kaylor]

Interesting, I did reply but it never made it to the thread. Here is my comment pulled from my email history on the 28th of Oct.

The changes I speak of have already been pushed to Nuget.

"I have reproduced the issue locally and verified that changing the enum commit value from LazyFlush to None does fix the issue. Going to see the impact that this has on performance. I doubt it will have much, I noticed RavenDB defaults to None for this as well. I'll update when I've pushed the changes."

--
You received this message because you are subscribed to the Google Groups "Rhino Tools Dev" group.

To view this discussion on the web visit https://groups.google.com/d/msg/rhino-tools-dev/-/QBPrcPjiFVQJ.

[cocowalla]

That worked, thanks!