Will Delay Interval is not working as expected

[wlisac]

Environment

• VerneMQ Version: 1.9.0
• Docker: erlio/docker-vernemq:latest
• VerneMQ configuration (vernemq.conf) default, with this env var set:
  • DOCKER_VERNEMQ_LISTENER__TCP__ALLOWED_PROTOCOL_VERSIONS=3,4,5
• Cluster size/standalone: Single docker container

Expected behavior

I'm expecting the Will Delay Interval to delay the publishing of the Will Message after closing the network connection.

Actual behaviour

• Connect to VerneMQ broker using version 5.0 of the MQTT protocol with a Session Expiry Interval of 60 and a Will Delay Interval of 10.

  MQ Telemetry Transport Protocol, Connect Command
      Header Flags: 0x10, Message Type: Connect Command
          0001 .... = Message Type: Connect Command (1)
          .... 0000 = Reserved: 0
      Msg Len: 86
      Protocol Name Length: 4
      Protocol Name: MQTT
      Version: MQTT v5.0 (5)
      Connect Flags: 0xc6, User Name Flag, Password Flag, QoS Level: At most once delivery (Fire and Forget), Will Flag, Clean Session Flag
          1... .... = User Name Flag: Set
          .1.. .... = Password Flag: Set
          ..0. .... = Will Retain: Not set
          ...0 0... = QoS Level: At most once delivery (Fire and Forget) (0)
          .... .1.. = Will Flag: Set
          .... ..1. = Clean Session Flag: Set
          .... ...0 = (Reserved): Not set
      Keep Alive: 60
      Properties
          Total Length: 5
          ID: Session Expiry Interval (0x11)
          Value: 60
      Client ID Length: 13
      Client ID: WillPublisher
      Will Properties
          Total Length: 7
          ID: Will Delay Interval (0x18)
          Value: 10
          ID: Payload Format Indicator (0x01)
          Value: 1
      Will Topic Length: 10
      Will Topic: will-topic
      Will Message Length: 7
      Will Message: Goodbye
      User Name Length: 7
      User Name: mqttnio
      Password Length: 15
      Password: mqttniopassword
  

• Receive a CONNACK from VerneMQ

  MQ Telemetry Transport Protocol, Connect Ack
      Header Flags: 0x20, Message Type: Connect Ack
          0010 .... = Message Type: Connect Ack (2)
          .... 0000 = Reserved: 0
      Msg Len: 3
      Acknowledge Flags: 0x00
          0000 000. = Reserved: Not set
          .... ...0 = Session Present: Not set
      Reason Code: Success (0)
      Properties
          Total Length: 0
  

• Close the network connection without sending a Disconnect Notification

• Notice that the Will Message is published immediately (I expected a 10 second delay)

Additional Notes

I'm detecting the Will Message being published using a different client that's subscribed to the will-topic topic.

I tested this flow using the mosquito broker and it's working as expected (the Will Delay Interval is being honored).

I'm working on writing an MQTT client and I'm hoping to understand if this might be a bug in VerneMQ.

Here are some relevant notes from the MQTT 5.0 protocol spec:

The Will Message MUST be published after the Network Connection is subsequently closed and either the Will Delay Interval has elapsed or the Session ends, unless the Will Message has been deleted by the Server on receipt of a DISCONNECT packet with Reason Code 0x00 (Normal disconnection) or a new Network Connection for the ClientID is opened before the Will Delay Interval has elapsed [MQTT-3.1.2-8].

I'm happy to provide more details as needed.

Thanks,
Will

[ioolkos]

@wlisac thanks!
@larshesel did we address this?

[larshesel]

Hi @wlisac, I looked into this, and as we had a test case covering this exactly I tried to vary a bit the settings (clean_start=true/false), the will delay etc, but I wasn't able to verify the issue. I would have like to try to test this with a cli client, but the paho c clients doesnt' seem to support setting the will delay. Which client do you use to verify this?

For reference the testcase in our test suite: https://github.com/vernemq/vernemq/blob/master/apps/vmq_server/test/vmq_last_will_SUITE.erl#L158

[wlisac]

@larshesel I'm testing with my work-in-progress client, but I was also able to reproduce using MQTT JS.

Check out test.js in the archive.

mqtt-js-test.zip

// Start VerneMQ broker

// Listen for will message on a different client
// $ mosquitto_sub -h localhost -p 1883 -t 'will-topic' -d

// Run this file using node
// $ node test.js

// Notice the delay is not honored using VerneMQ. It is honored using the Mosquitto broker.

const mqtt = require('mqtt');

const options = {
    will: {
        topic: 'will-topic',
        payload: 'hello',
        properties: {
            willDelayInterval: 10
        }
    },
    protocolVersion: 5,
    clientId: 'mqttjs_' + Math.random().toString(16).substr(2, 8),
    properties: {
        sessionExpiryInterval: 60
    }
}

const client  = mqtt.connect('mqtt:https://localhost:1883', options);

client.on('connect', function () {
    throw 'Goodbye!'
})

[wlisac]

@larshesel here's possibly a simpler way to reproduce using mosquitto_pub.

$ mosquitto_sub -h localhost -p 1883 -t 'test' -d --will-payload 'goodbye' --will-topic 'will-topic' -V 5 -D WILL will-delay-interval 10 -D CONNECT session-expiry-interval 60

And terminate the connection with ⌃c to trigger a disconnect.

[larshesel]

Hi @wlisac

I can indeed reproduce it with the mosquitto_sub cli tool. I'll dig deeper!

Bonus for me here is that I now finally updated my mosquitto clients to the
newest release (the standard debian packages doesn't yet support MQTT v5).

[wlisac]

Awesome – another edge case to watch out for when fixing this is handling when the Will Delay Interval is longer than Session Expiry Interval. I recently opened an issue on the mosquitto broker for this: eclipse/mosquitto#1401

Some helpful notes from the 5.0 spec:

The Server delays publishing the Client’s Will Message until the Will Delay Interval has passed or the Session ends, whichever happens first.

Non-normative comment
The Client can arrange for the Will Message to notify that Session Expiry has occurred by setting the Will Delay Interval to be longer than the Session Expiry Interval and sending DISCONNECT with Reason Code 0x04 (Disconnect with Will Message).

[larshesel]

Hi @wlisac

I think I figured out what is going on, and it's a bit embarrassing that I
forgot about it. By default the max allowed will delay is set to 0. From the VerneMQ config file:

## The maximum delay for a last will message. This setting
## applies only to MQTTv5 sessions and overrides the value provided by
## the client.
## The delay should be an integer followed by one of 's', 'h' 'd',
## 'w', 'm', 'y' for day, week, month, and year.
## 
## Default: 0s
## 
## Acceptable values:
##   - text
## max_last_will_delay = 0s

Remembering back we introduced this configuration to have a way to
decide from the broker what the client should be allowed to do. The question
was, what should the default be and I think we made a mistake here, perhaps we
should have a default which is session_expiration or max or similar?

[larshesel]

Btw @wlisac We really appreciate your feedback here and would like to acknowledge your efforts (albeit in a very minimal way) by adding you to the THANKS file: https://github.com/vernemq/vernemq/blob/master/THANKS

I'd then add you as Will Lisac (@wlisac) if that's OK with you?

[larshesel]

I created a PR #1310 which introduces a new value to last_max_will_delay called client.

[larshesel]

I think we can close this for now :)

[wlisac]

@larshesel I tested the changes in your branch and the delay is now working as expected. Thanks!

And I'd be honored to be mentioned in the THANKS file – appreciate that 😊

As far as the max_last_will_delay configuration, I also think there should likely be a max_session_expiration instead.

The broker doesn't have a way to communicate to the client that the will delay interval isn't what the client sent, but it does have a way to communicate the session expiry interval is different than requested (via CONNACK in 5.0 spec).

And since the Will Delay Interval is effectively capped to the session expiry interval, I think you accomplish the same goal :)

The Server delays publishing the Client’s Will Message until the Will Delay Interval has passed or the Session ends, whichever happens first.

[larshesel]

As far as the max_last_will_delay configuration, I also think there should likely be a max_session_expiration instead.

I'm not sure that's needed as this always holds as you mention and one could achieve this by simply setting the max_last_will_delay to something large (which is actually what the client setting does - it sets it to the maximum possible). And as you mention, per the spec the Will Delay Interval is always (must) be capped by the Session Expiry Interval.

[larshesel]

Added a commit to THANKS file in the #1310 PR : https://github.com/vernemq/vernemq/pull/1310/files#diff-df89e795839ea42c0425275caa0e08fcR25

[wlisac]

@larshesel It's possible that I'm misunderstanding, but it seems like there is still a config point (max_last_will_delay) that can be used to override the will delay interval specified by the client.

It seems like this config point shouldn't allowed since there isn't a way to communicate this actual will delay interval back to the client. And if the will delay interval is ever forced to be lower than the session expiry max, then that would seem to violate the spec.

I'm not sure I'm communicating my point well here 😅 – to flip it around – what is the use case for the max_last_will_delay config?

[larshesel]

You're right that this violates the spec if used. The idea is (like many other features, like max_message_size, max_inflight_messages etc) is to give the broker operators and MQTT application designers control. Many of these settings can also be changed on a per client basis (via auth_on_register modifiers) so if someone needs max_message_size to be small for most clients, but large for others, then this is possible. We had the same idea for max_last_will_delay - without it you have to trust clients to do the right thing - so it's not really that we have a known use case for it, but seemed like a logical thing to add, though, if we had thought a bit more/longer about it, I think we probably wouldn't have.