precondition_failed: invalid expiration

[Tim Bailie]

We are using RabbitMQ and MassTransit in our application and are getting random invalid expiration errors that look like below. One they start happening, it seems like they are likely to increase in volume. So far, it appears restarting the RabbitMQ windows service doesn't completely solve the problem. Rebooting the servers does seem to from what we've gathered so far. We are running RabbitMQ on one machine. This machine also has both publishers and consumers on it. We also have another machine that RabbitMQ is not running on that publishes and consumes from them. We don't believe we are setting a TimeToLive(TTL) or expiration anywhere. We are at a loss. Any ideas?

Error: operation basic.publish caused a channel exception precondition_failed: invalid expiration '-21996': {value_negative,-21996}

[Wesley Peng]

on 2019/11/5 2:21, Tim Bailie wrote:
> We are using RabbitMQ and MassTransit in our application and are getting
> random invalid expiration errors that look like below. One they start
> happening, it seems like they are likely to increase in volume. So far,
> it appears restarting the RabbitMQ windows service doesn't completely
> solve the problem. Rebooting the servers does seem to from what we've
> gathered so far. We are running RabbitMQ on one machine. This machine
> also has both publishers and consumers on it. We also have another
> machine that RabbitMQ is not running on that publishes and consumes from
> them. We don't believe we are setting a TimeToLive(TTL) or expiration
> anywhere. We are at a loss. Any ideas?

Before the community can help you, we must know this information:

Version of Erlang and RabbitMQ
Operating system and version
RabbitMQ configuration files
RabbitMQ log files, or log file entries
Exact error output
Exact commands you are running, or code you are running

regards.

[Sarah Pliner]

I work with Tim, who is off for a few days. I am including most of the information you requested below. We are using MassTransit (version 5.5) for our message management and are also looking into that to see if that is the issue.

Erlang OTP 21 10.0.1

RabbitMQ Server 3.7.15

Windows Server 2012 R2 - version NT 6.3

Configuration file is attached.

Log file entries:

2019-11-04 07:20:33.040 [error] <0.28280.5> Supervisor {<0.28280.5>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.28274.5>, <<"<rab...@VMPLENDSVCSP03.2.28274.5>">>) at undefined exit with reason noproc in context shutdown_error

2019-11-04 07:21:51.192 [error] <0.28434.5> Supervisor {<0.28434.5>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.28427.5>, <<"<rab...@VMPLENDSVCSP03.2.28427.5>">>) at undefined exit with reason shutdown in context shutdown_error

2019-11-04 08:01:48.451 [error] <0.859.6> Supervisor {<0.859.6>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.852.6>, <<"<rab...@VMPLENDSVCSP03.2.852.6>">>) at undefined exit with reason shutdown in context shutdown_error

2019-11-04 09:01:41.217 [error] <0.24782.2> Channel error on connection <0.2026.0> (10.33.7.132:49347 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 27:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9377': {value_negative,-9377}

2019-11-04 09:01:41.347 [error] <0.8425.6> Channel error on connection <0.2026.0> (10.33.7.132:49347 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 27:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9501': {value_negative,-9501}

2019-11-04 09:01:41.412 [error] <0.24495.2> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 59:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9574': {value_negative,-9574}

2019-11-04 09:01:41.556 [error] <0.8442.6> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 59:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9704': {value_negative,-9704}

2019-11-04 09:01:51.724 [error] <0.23935.2> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 39:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9473': {value_negative,-9473}

2019-11-04 09:01:52.015 [error] <0.30266.5> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 70:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9762': {value_negative,-9762}

2019-11-04 09:01:52.046 [error] <0.8494.6> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 70:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9796': {value_negative,-9796} 

Error output:

MassTransit.RabbitMqTransport.MessageNotConfirmedException: rabbitmq://icasbus.cmutual.com/icasbus/VMPLENDSVCSP04_dotnet_bus_k4yyyyns1oyfyz5ibdmsyxmjga => The message was not confirmed: PRECONDITION_FAILED - invalid expiration '-9574': {value_negative,-9574}     at MassTransit.RabbitMqTransport.Contexts.RabbitMqModelContext.MassTransit.RabbitMqTransport.ModelContext.BasicPublishAsync(String exchange, String routingKey, Boolean mandatory, IBasicProperties basicProperties, Byte[] body, Boolean awaitAck)     at MassTransit.Internals.Extensions.TaskExtensions.WithCancellation(Task task, CancellationToken cancellationToken)     at MassTransit.RabbitMqTransport.Transport.RabbitMqSendTransport.SendPipe`1.Send(ModelContext modelContext)     at MassTransit.RabbitMqTransport.Transport.RabbitMqSendTransport.SendPipe`1.Send(ModelContext modelContext)     at GreenPipes.Agents.PipeContextSupervisor`1.GreenPipes.IPipeContextSource<TContext>.Send(IPipe`1 pipe, CancellationToken cancellationToken)     at GreenPipes.Agents.PipeContextSupervisor`1.GreenPipes.IPipeContextSource<TContext>.Send(IPipe`1 pipe, CancellationToken cancellationToken)     at GreenPipes.Agents.PipeContextSupervisor`1.GreenPipes.IPipeContextSource<TContext>.Send(IPipe`1 pipe, CancellationToken cancellationToken)     at MassTransit.Context.BaseConsumeContext.RespondAsync[T](T message)     at CUNAMutual.ICAS.ServiceBus.Receiver.ResponseProducingConsumerBase`2.RespondWithSuccess(ConsumeContext context, TEvent event, Func`2 eventToResultConversion)     at CUNAMutual.ICAS.Consumers.IndividualContract.RetrieveIndividualContractConsumer.Consume(ConsumeContext`1 context) 

Commands:
We are using MassTransit to connect and handle messages to/from the queues. Let me know if you think it would help for me to provide the specific objects/methods we are using from that component.

[Luke Bakken]

Hi Sarah,

RabbitMQ validates parameters when messages are published. In your case, a negative value is passed for message expiration.

This is a bug in MassTransit, or an error in how you're using it.

https://groups.google.com/forum/#!topic/masstransit-discuss/YLoGe6z1O0s/discussion

Thanks,

Luke

2019-11-04 07:20:33.040 [error] <0.28280.5> Supervisor {<0.28280.5>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.28274.5>, <<"<rabbit@VMPLENDSVCSP03.2.28274.5>">>) at undefined exit with reason noproc in context shutdown_error

2019-11-04 07:21:51.192 [error] <0.28434.5> Supervisor {<0.28434.5>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.28427.5>, <<"<rabbit@VMPLENDSVCSP03.2.28427.5>">>) at undefined exit with reason shutdown in context shutdown_error

2019-11-04 08:01:48.451 [error] <0.859.6> Supervisor {<0.859.6>,amqp_channel_sup_sup} had child channel_sup started with amqp_channel_sup:start_link(direct, <0.852.6>, <<"<rabbit@VMPLENDSVCSP03.2.852.6>">>) at undefined exit with reason shutdown in context shutdown_error

2019-11-04 09:01:41.217 [error] <0.24782.2> Channel error on connection <0.2026.0> (10.33.7.132:49347 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 27:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9377': {value_negative,-9377}

2019-11-04 09:01:41.347 [error] <0.8425.6> Channel error on connection <0.2026.0> (10.33.7.132:49347 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 27:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9501': {value_negative,-9501}

2019-11-04 09:01:41.412 [error] <0.24495.2> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 59:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9574': {value_negative,-9574}

2019-11-04 09:01:41.556 [error] <0.8442.6> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 59:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9704': {value_negative,-9704}

2019-11-04 09:01:51.724 [error] <0.23935.2> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 39:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9473': {value_negative,-9473}

2019-11-04 09:01:52.015 [error] <0.30266.5> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 70:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9762': {value_negative,-9762}

2019-11-04 09:01:52.046 [error] <0.8494.6> Channel error on connection <0.2206.0> (10.33.7.132:49357 -> 10.33.7.132:5672, vhost: 'icasbus', user: 'SA-ICASWS-P'), channel 70:

operation basic.publish caused a channel exception precondition_failed: invalid expiration '-9796': {value_negative,-9796} 

[Tim Bailie]

Thank for the reply. I've reviewed the content of the link. It seems that it was believe that the issue there was fixed in MT3, or at least believed to be. We are using MassTransit version 5.5.5. I've looked thru our code and all of our configuration and don't believe we are setting a message expiration or TTL anywhere so we'd be going whatever MassTransit  and/or Rabbit MQ would use as a default. We basically don't want the messages to expire. I haven't yet found what would be making this value negative.

[Luke Bakken]

Hi Tim,

RabbitMQ and the RabbitMQ .NET client library do not ever set a message TTL unless instructed to do so.

We don't normally try to diagnose issues with libraries that use the .NET client, like MassTransit. If you can provide a way to reliably reproduce this, I'm sure the problem could be found quickly.

Like I said, this is an issue with MassTransit. I suggest finding all code points within MassTransit where message expiration is set. Then, add debug logging or some other mechanism to know when this is done (with stack trace), and run your application until the condition is met.

I'm wondering if the server running your application experiences clock drift or time/date reset that causes negative values to be created within MassTransit.

Thanks,

Luke

[Tim Bailie]

We believe we've identified and rectified the issue. It seems, unknown to us, our companies domain controllers somehow got out of synch in regards to their date/time. As our servers checked their clocks, depending on which domain controller they connected to, they would get different current times. When our 2 servers connected to different domain controllers in a certain way, they would get different enough date/times such that this error would occur. The issue with our domain controllers has been corrected. So, in summary, if someone else gets this error, make sure the servers you are running on are in synch with their date/times.

Thanks to those who helped!

[Luke Bakken]

Hi Tim,

That is unexpected! Thank you for following up with the list.