SetRequestExpiration can result in a negative value

[Thomas Tomanek]

Hi guys,

I've just been debugging some issues I've had with MT + Rabbitmq in a failover cluster behind a netscaler LB.

It looks like when you set the message expiry in MT with SetRequestExpiration and then the RMQ node goes down that the bus was connected to, in the process of retrying (which normally works great and will end up with another connection to the second broker) it ends up with a negative value in the expiration, which rabbitmq dislikes. I'm not 100% sure but it looks like at this point the bus gets into a slightly unrecoverable state.

the error I receive back from RMQ looks like:

709 13:59:11 - Error - Waiting for pending confirms threw an exception RabbitMQ.Client.Exceptions.AlreadyClosedException: The AMQP operation was interrupted: AMQP close-reason, initiated by Peer, code=406, text="PRECONDITION_FAILED - invalid expiration '-5296': {value_negative,-5296}", classId=60, methodId=40, cause=

And I've confirmed the negative value comes from:

           

 properties.Expiration =
      (value.Kind == DateTimeKind.Utc
        ? value - SystemUtil.UtcNow
        : value - SystemUtil.Now).
        TotalMilliseconds.ToString("F0", CultureInfo.InvariantCulture);

...in OutboundRabbitMqTransport:Send

So the 'value' comes out of the send context, so it makes sense that you end up with negative values after the time has taken > expiration I guess.

I've removed all TTLs from our codebase for the time being.

Haven't had chance to try MT3...might be fixed in there.

Cheers,

Tom

[Thomas Tomanek]

Just had a peak into mt3 and it does look like it'll be fine there (although not tested it!)

properties.Expiration = context.TimeToLive.Value.TotalMilliseconds.ToString("F0", CultureInfo.InvariantCulture);

 using a TimeSpan rather than trying to work it out from two datetimes

[Chris Patterson]

We use a timespan and it works out well, like FromSeconds(30) for responses to web queries, etc. And yes, the F0 stuff was added at some point, it used to be completely broken (pre 2.9 I think).

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to masstransit-dis...@googlegroups.com.
To post to this group, send email to masstrans...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/masstransit-discuss/43f4906a-7b28-4a77-83b0-3fda959da649%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Jerome Haltom]

I think I'm also experiencing this issue, in 2.9. Getting my bus stuck in an error loop where a RabbitMQ condition is detecting a 34s negative value. I'm using SetExpirationTime(DateTime.Now.AddSeconds(5).

=ERROR REPORT==== 11-Mar-2015::15:29:05 ===

Channel error on connection <0.791.0> ([::1]:50148 -> [::1]:5672, vhost: 'isis', user: 'isis'), channel 2:

{amqp_error,precondition_failed,

            "invalid expiration '-34470': {value_negative,-34470}",

            'basic.publish'}

It's not actually taking 30 seconds for the message to actually be sent. But, there's some code somewhere that is calculating a negative value still. I'm using 2.9.0.

It seems like worst case for this would be to hard code a floor of 0. 0 is at least a valid RabbitMQ value, and won't result in an error, and reflects what is happening: The time is expiring before it hits the queue.

[Jerome Haltom]

Oh, that said, there is still a real problem here: why do I have a 30 second delay in here? The code looks like this:

                        bus.Publish<SemaphoreMessage>(new SemaphoreMessage()

                        {

                            SemaphoreId = semaphoreId,

                            InstanceId = id,

                            Timestamp = DateTime.UtcNow,

                            Sort = sort,

                            Status = SemaphoreStatus.Acquire,

                        }, x => x.SetExpirationTime(DateTime.Now.AddSeconds(5)).SetRetryCount(0));

[Jerome Haltom]

Also, this isn't about SetRequestExpiration, it's about SetExpirationTime.

[Thomas Tomanek]

Yeah it looks like they're doing the same thing only that SetRequestExpiration allows you to specify a TimeSpan (but ends up being DateTime.UtcNow + Timespan).

Looks like it really needs changing to just be sending the value of the TimeStamp like MT3. Will fork and have a play with doing it without breaking any existing stuff.