search

FoundatioFx / Foundatio

Pluggable foundation blocks for building distributed apps.
Apache License 2.0
1.99k stars 244 forks source link

Different Message Type in Queue with same name #151

Closed tboeker closed 5 years ago

tboeker commented 5 years ago

I have two different command types and want to push them into the same queue. i created a QueueFactory which returns an IQueue. if i use the same queue name for both command types, the handler doesn't work as i would expect. have a look at the sample code:

` using System; using System.Threading.Tasks; using Foundatio.Queues; using StackExchange.Redis;

namespace Sample { internal class Program { private static bool AllQueuesTheSameName;

    private static IQueue<T> CreateQueue<T>() where T : class
    {
        var name = typeof(T).FullName.Trim().Replace(".", string.Empty).ToLower();

        if (AllQueuesTheSameName)
            name = "cmd";

        return new RedisQueue<T>(new RedisQueueOptions<T>
        {
            Name = name,
            ConnectionMultiplexer = ConnectionMultiplexer.Connect("localhost")
        });
    }

    private static async Task HandlerCommand1Async()
    {
        var q = CreateQueue<Command1>();

        await q.StartWorkingAsync((entry, token) =>
        {
            Console.WriteLine($"{DateTime.UtcNow:O}: Handler1\t{entry.Value.GetType().Name} {entry.Value.Id}");
            return Task.CompletedTask;
        });
    }

    private static async Task HandlerCommand2Async()
    {
        var q = CreateQueue<Command2>();

        await q.StartWorkingAsync((entry, token) =>
        {
            Console.WriteLine($"{DateTime.UtcNow:O}: Handler1\t{entry.Value.GetType().Name} {entry.Value.Id}");
            return Task.CompletedTask;
        }, true);
    }

    private static void Main()
    {
        AllQueuesTheSameName = true;
        Console.WriteLine($"AllQueuesTheSameName: {AllQueuesTheSameName}");

        HandlerCommand1Async().Wait();
        HandlerCommand2Async().Wait();

        Task.Delay(1000).Wait();

        Publish1Async().Wait();
        Publish2Async().Wait();

        Console.ReadLine();
    }

    private static async Task Publish1Async()
    {
        var q = CreateQueue<Command1>();

        for (var i = 0; i < 10; i++)
        {
            var cmd = new Command1(100 + i);
            Console.WriteLine($"{DateTime.UtcNow:O}: Publish\t{cmd.GetType().Name} {cmd.Id}");
            await q.EnqueueAsync(cmd);
        }
    }

    private static async Task Publish2Async()
    {
        var q = CreateQueue<Command2>();

        for (var i = 0; i < 10; i++)
        {
            var cmd = new Command2(200 + i);
            Console.WriteLine($"{DateTime.UtcNow:O}: Publish\t{cmd.GetType().Name} {cmd.Id}");
            await q.EnqueueAsync(cmd);
        }
    }
}

public class Command1
{
    public Command1(int id)
    {
        Id = id;
    }

    public int Id { get; }
}

public class Command2
{
    public Command2(int id)
    {
        Id = id;
    }

    public int Id { get; }
}

}

`

if every command gets its own queue name the result is:

`

AllQueuesTheSameName: False 2019-07-25T18:57:44.7260862Z: Publish Command1 100 2019-07-25T18:57:44.7675212Z: Publish Command1 101 2019-07-25T18:57:44.7725089Z: Publish Command1 102 2019-07-25T18:57:44.7766590Z: Publish Command1 103 2019-07-25T18:57:44.7803840Z: Publish Command1 104 2019-07-25T18:57:44.7849787Z: Publish Command1 105 2019-07-25T18:57:44.7872733Z: Handler1 Command1 100 2019-07-25T18:57:44.7895419Z: Publish Command1 106 2019-07-25T18:57:44.7934077Z: Handler1 Command1 101 2019-07-25T18:57:44.7940201Z: Publish Command1 107 2019-07-25T18:57:44.7983073Z: Publish Command1 108 2019-07-25T18:57:44.7995599Z: Handler1 Command1 102 2019-07-25T18:57:44.8030281Z: Publish Command1 109 2019-07-25T18:57:44.8054972Z: Handler1 Command1 103 2019-07-25T18:57:44.8104019Z: Handler1 Command1 104 2019-07-25T18:57:44.8173993Z: Publish Command2 200 2019-07-25T18:57:44.8198631Z: Handler1 Command1 105 2019-07-25T18:57:44.8245379Z: Handler1 Command1 106 2019-07-25T18:57:44.8306788Z: Handler1 Command1 107 2019-07-25T18:57:44.8351557Z: Handler1 Command1 108 2019-07-25T18:57:44.8362959Z: Publish Command2 201 2019-07-25T18:57:44.8399255Z: Publish Command2 202 2019-07-25T18:57:44.8408061Z: Handler1 Command1 109 2019-07-25T18:57:44.8440239Z: Publish Command2 203 2019-07-25T18:57:44.8449628Z: Handler1 Command2 200 2019-07-25T18:57:44.8471449Z: Publish Command2 204 2019-07-25T18:57:44.8501180Z: Publish Command2 205 2019-07-25T18:57:44.8532053Z: Publish Command2 206 2019-07-25T18:57:44.8564446Z: Publish Command2 207 2019-07-25T18:57:44.8595215Z: Publish Command2 208 2019-07-25T18:57:44.8629140Z: Publish Command2 209 2019-07-25T18:57:44.8684110Z: Handler1 Command2 201 2019-07-25T18:57:44.8748800Z: Handler1 Command2 202 2019-07-25T18:57:44.8809065Z: Handler1 Command2 203 2019-07-25T18:57:44.8882610Z: Handler1 Command2 204 2019-07-25T18:57:44.8948945Z: Handler1 Command2 205 2019-07-25T18:57:44.9012971Z: Handler1 Command2 206 2019-07-25T18:57:44.9077468Z: Handler1 Command2 207 2019-07-25T18:57:44.9145404Z: Handler1 Command2 208 2019-07-25T18:57:44.9210442Z: Handler1 Command2 209

`

looks fine and in the right order.

if i use the same name for each queue the result is:

`

AllQueuesTheSameName: True 2019-07-25T18:58:40.1263076Z: Publish Command1 100 2019-07-25T18:58:40.1596883Z: Publish Command1 101 2019-07-25T18:58:40.1632048Z: Publish Command1 102 2019-07-25T18:58:40.1667221Z: Publish Command1 103 2019-07-25T18:58:40.1718992Z: Publish Command1 104 2019-07-25T18:58:40.1757325Z: Handler1 Command1 100 2019-07-25T18:58:40.1766131Z: Publish Command1 105 2019-07-25T18:58:40.1811286Z: Publish Command1 106 2019-07-25T18:58:40.1853968Z: Handler1 Command1 102 2019-07-25T18:58:40.1872429Z: Publish Command1 107 2019-07-25T18:58:40.1886490Z: Handler1 Command2 101 2019-07-25T18:58:40.1907464Z: Handler1 Command1 103 2019-07-25T18:58:40.1913289Z: Publish Command1 108 2019-07-25T18:58:40.1952245Z: Publish Command1 109 2019-07-25T18:58:40.1961855Z: Handler1 Command1 104 2019-07-25T18:58:40.2010647Z: Handler1 Command1 105 2019-07-25T18:58:40.2072325Z: Handler1 Command1 106 2019-07-25T18:58:40.2078624Z: Publish Command2 200 2019-07-25T18:58:40.2120566Z: Handler1 Command1 107 2019-07-25T18:58:40.2158971Z: Publish Command2 201 2019-07-25T18:58:40.2211824Z: Handler1 Command1 108 2019-07-25T18:58:40.2237410Z: Publish Command2 202 2019-07-25T18:58:40.2267316Z: Handler1 Command2 109 2019-07-25T18:58:40.2274573Z: Handler1 Command1 200 2019-07-25T18:58:40.2280557Z: Publish Command2 203 2019-07-25T18:58:40.2322018Z: Publish Command2 204 2019-07-25T18:58:40.2356484Z: Handler1 Command1 201 2019-07-25T18:58:40.2365110Z: Handler1 Command2 202 2019-07-25T18:58:40.2373680Z: Publish Command2 205 2019-07-25T18:58:40.2453111Z: Publish Command2 206 2019-07-25T18:58:40.2458136Z: Handler1 Command1 203 2019-07-25T18:58:40.2491908Z: Handler1 Command2 204 2019-07-25T18:58:40.2503680Z: Publish Command2 207 2019-07-25T18:58:40.2530496Z: Handler1 Command1 205 2019-07-25T18:58:40.2572651Z: Publish Command2 208 2019-07-25T18:58:40.2642463Z: Publish Command2 209 2019-07-25T18:58:40.2675953Z: Handler1 Command2 207 2019-07-25T18:58:40.2688388Z: Handler1 Command1 206 2019-07-25T18:58:40.2749948Z: Handler1 Command1 208 2019-07-25T18:58:40.2770564Z: Handler1 Command2 209 `

there is a mismatch at the command type

niemyjski commented 5 years ago

Your log message in both has handler1 does this make a difference? Console.WriteLine($"{DateTime.UtcNow:O}: Handler1\t{entry.Value.GetType().Name} {entry.Value.Id}");

tboeker commented 5 years ago

Command1 has ids from 100 to 109, Command2 has ids from 200 to 209. It seems like there is something wrong with the "type detection" or serialization.

AllQueuesTheSameName: True 2019-07-25T18:58:40.1263076Z: Publish Command1 100 2019-07-25T18:58:40.1596883Z: Publish Command1 101 2019-07-25T18:58:40.1632048Z: Publish Command1 102 2019-07-25T18:58:40.1667221Z: Publish Command1 103 2019-07-25T18:58:40.1718992Z: Publish Command1 104 2019-07-25T18:58:40.1757325Z: Handler1 Command1 100 2019-07-25T18:58:40.1766131Z: Publish Command1 105 2019-07-25T18:58:40.1811286Z: Publish Command1 106 2019-07-25T18:58:40.1853968Z: Handler1 Command1 102 => should be Command1 101 , not 102, it is the wrong order 2019-07-25T18:58:40.1872429Z: Publish Command1 107 2019-07-25T18:58:40.1886490Z: Handler1 Command2 101 => should Be Command1 101, there is no Command2 in the queue at this moment, and it is the wrong order 2019-07-25T18:58:40.1907464Z: Handler1 Command1 103 2019-07-25T18:58:40.1913289Z: Publish Command1 108 2019-07-25T18:58:40.1952245Z: Publish Command1 109 => Last Command1 Publish 2019-07-25T18:58:40.1961855Z: Handler1 Command1 104 2019-07-25T18:58:40.2010647Z: Handler1 Command1 105 2019-07-25T18:58:40.2072325Z: Handler1 Command1 106 2019-07-25T18:58:40.2078624Z: Publish Command2 200 => First Command2 Publish 2019-07-25T18:58:40.2120566Z: Handler1 Command1 107 2019-07-25T18:58:40.2158971Z: Publish Command2 201 2019-07-25T18:58:40.2211824Z: Handler1 Command1 108 2019-07-25T18:58:40.2237410Z: Publish Command2 202 2019-07-25T18:58:40.2267316Z: Handler1 Command2 109 => should be Command1 109 2019-07-25T18:58:40.2274573Z: Handler1 Command1 200 2019-07-25T18:58:40.2280557Z: Publish Command2 203 2019-07-25T18:58:40.2322018Z: Publish Command2 204 2019-07-25T18:58:40.2356484Z: Handler1 Command1 201 => should be Command2 201, 2019-07-25T18:58:40.2365110Z: Handler1 Command2 202 2019-07-25T18:58:40.2373680Z: Publish Command2 205 2019-07-25T18:58:40.2453111Z: Publish Command2 206 2019-07-25T18:58:40.2458136Z: Handler1 Command1 203 => should be Command2 203, 2019-07-25T18:58:40.2491908Z: Handler1 Command2 204 2019-07-25T18:58:40.2503680Z: Publish Command2 207 2019-07-25T18:58:40.2530496Z: Handler1 Command1 205 => should be Command2 205, 2019-07-25T18:58:40.2572651Z: Publish Command2 208 2019-07-25T18:58:40.2642463Z: Publish Command2 209 2019-07-25T18:58:40.2675953Z: Handler1 Command2 207 2019-07-25T18:58:40.2688388Z: Handler1 Command1 206 => should be Command2 206, 2019-07-25T18:58:40.2749948Z: Handler1 Command1 208 => should be Command2 208, 2019-07-25T18:58:40.2770564Z: Handler1 Command2 209 `

tboeker commented 5 years ago

Your log message in both has handler1 does this make a difference? Console.WriteLine($"{DateTime.UtcNow:O}: Handler1\t{entry.Value.GetType().Name} {entry.Value.Id}");

the Handler1 is only a text

niemyjski commented 5 years ago

Thanks, I'll take a look

niemyjski commented 5 years ago

I'm not able to reproduce this issue with the following test:

[Fact]
public async Task CanHaveDifferentMessageTypeInQueueWithSameNameAsync() {
    await HandlerCommand1Async();
    await HandlerCommand2Async();

    await Task.Delay(1000);

    await Publish1Async();
    await Publish2Async();
}

private IQueue<T> CreateQueue<T>(bool allQueuesTheSameName = true) where T : class {
    var name = typeof(T).FullName.Trim().Replace(".", string.Empty).ToLower();

    if (allQueuesTheSameName)
        name = "cmd";

    var queue = new RedisQueue<T>(o => o
        .ConnectionMultiplexer(SharedConnection.GetMuxer())
        .Name(name)
        .LoggerFactory(Log)
    );

    _logger.LogDebug("Queue Id: {queueId}", queue.QueueId);
    return queue;
}

private async Task HandlerCommand1Async() {
    var q = CreateQueue<Command1>();

    await q.StartWorkingAsync((entry, token) => {
        _logger.LogInformation($"{SystemClock.UtcNow:O}: Handler1\t{entry.Value.GetType().Name} {entry.Value.Id}");
        Assert.InRange(entry.Value.Id, 100, 199);
        return Task.CompletedTask;
    });
}

private async Task HandlerCommand2Async() {
    var q = CreateQueue<Command2>();

    await q.StartWorkingAsync((entry, token) => {
        _logger.LogInformation($"{SystemClock.UtcNow:O}: Handler2\t{entry.Value.GetType().Name} {entry.Value.Id}");
        Assert.InRange(entry.Value.Id, 200, 299);
        return Task.CompletedTask;
    }, true);
}

private async Task Publish1Async() {
    var q = CreateQueue<Command1>();

    for (var i = 0; i < 10; i++) {
        var cmd = new Command1(100 + i);
        _logger.LogInformation($"{DateTime.UtcNow:O}: Publish\tCommand1 {cmd.Id}");
        await q.EnqueueAsync(cmd);
    }
}

private async Task Publish2Async() {
    var q = CreateQueue<Command2>();

    for (var i = 0; i < 10; i++) {
        var cmd = new Command2(200 + i);
        _logger.LogInformation($"{DateTime.UtcNow:O}: Publish\tCommand2 {cmd.Id}");
        await q.EnqueueAsync(cmd);
    }
}

public class Command1 {
    public Command1(int id) {
        Id = id;
    }

    public int Id { get; }
}

public class Command2 {
    public Command2(int id) {
        Id = id;
    }

    public int Id { get; }
}

I added asserts to double check my work. Also here is the output:

55:48.49387 I:RedisQueueTests - 2019-07-30T12:55:48.4925860Z: Publish   Command1 100
55:48.64170 I:RedisQueueTests - 2019-07-30T12:55:48.6416410Z: Publish   Command1 101
55:48.64415 I:RedisQueueTests - 2019-07-30T12:55:48.6441420Z: Publish   Command1 102
55:48.64590 I:RedisQueueTests - 2019-07-30T12:55:48.6458950Z: Publish   Command1 103
55:48.64780 I:RedisQueueTests - 2019-07-30T12:55:48.6477990Z: Publish   Command1 104
55:48.64973 I:RedisQueueTests - 2019-07-30T12:55:48.6497280Z: Publish   Command1 105
55:48.65134 I:RedisQueueTests - 2019-07-30T12:55:48.6513360Z: Publish   Command1 106
55:48.65286 I:RedisQueueTests - 2019-07-30T12:55:48.6528570Z: Publish   Command1 107
55:48.65446 I:RedisQueueTests - 2019-07-30T12:55:48.6544530Z: Publish   Command1 108
55:48.65641 I:RedisQueueTests - 2019-07-30T12:55:48.6564080Z: Publish   Command1 109
55:48.65902 I:RedisQueueTests - 2019-07-30T12:55:48.6588860Z: Publish   Command2 200
55:48.67351 I:RedisQueueTests - 2019-07-30T12:55:48.6735070Z: Publish   Command2 201
55:48.67598 I:RedisQueueTests - 2019-07-30T12:55:48.6759790Z: Publish   Command2 202
55:48.67846 I:RedisQueueTests - 2019-07-30T12:55:48.6784560Z: Publish   Command2 203
55:48.67871 I:RedisQueueTests - 2019-07-30T12:55:48.6786330Z: Handler1  Command1 100
55:48.67920 I:RedisQueueTests - 2019-07-30T12:55:48.6791690Z: Handler2  Command2 200
55:48.68091 I:RedisQueueTests - 2019-07-30T12:55:48.6809100Z: Publish   Command2 204
55:48.68288 I:RedisQueueTests - 2019-07-30T12:55:48.6828810Z: Publish   Command2 205
55:48.68291 I:RedisQueueTests - 2019-07-30T12:55:48.6829080Z: Handler1  Command1 101
55:48.68450 I:RedisQueueTests - 2019-07-30T12:55:48.6844920Z: Publish   Command2 206
55:48.68522 I:RedisQueueTests - 2019-07-30T12:55:48.6852140Z: Handler1  Command1 102
55:48.68646 I:RedisQueueTests - 2019-07-30T12:55:48.6864580Z: Publish   Command2 207
55:48.68762 I:RedisQueueTests - 2019-07-30T12:55:48.6876170Z: Handler1  Command1 103
55:48.68820 I:RedisQueueTests - 2019-07-30T12:55:48.6881930Z: Publish   Command2 208
55:48.69042 I:RedisQueueTests - 2019-07-30T12:55:48.6904150Z: Publish   Command2 209
55:48.69042 I:RedisQueueTests - 2019-07-30T12:55:48.6904200Z: Handler1  Command1 104
55:48.69175 I:RedisQueueTests - 2019-07-30T12:55:48.6917440Z: Handler2  Command2 201
55:48.69284 I:RedisQueueTests - 2019-07-30T12:55:48.6928330Z: Handler1  Command1 105
55:48.69519 I:RedisQueueTests - 2019-07-30T12:55:48.6951810Z: Handler2  Command2 202
55:48.69519 I:RedisQueueTests - 2019-07-30T12:55:48.6951810Z: Handler1  Command1 106
55:48.69723 I:RedisQueueTests - 2019-07-30T12:55:48.6972280Z: Handler1  Command1 107
55:48.69846 I:RedisQueueTests - 2019-07-30T12:55:48.6984530Z: Handler2  Command2 203
55:48.69981 I:RedisQueueTests - 2019-07-30T12:55:48.6998000Z: Handler1  Command1 108
55:48.70190 I:RedisQueueTests - 2019-07-30T12:55:48.7018940Z: Handler1  Command1 109
55:48.70190 I:RedisQueueTests - 2019-07-30T12:55:48.7018940Z: Handler2  Command2 204
55:48.70484 I:RedisQueueTests - 2019-07-30T12:55:48.7048350Z: Handler2  Command2 205
55:48.70848 I:RedisQueueTests - 2019-07-30T12:55:48.7084720Z: Handler2  Command2 206

If you can modify this test to recreate your issue please let me know by pasting the modified one below.

niemyjski commented 5 years ago

As stated before, I believe your sample had a console.writeline with the same exact output message for command one and command2 that caused this issue.