$SYS/broker/log/N "Connecting bridge ..." notification isn't initially published

[cjmaynard]

I want to have an MQTT client subscribe to both the $SYS/broker/log/N and $SYS/broker/connection/+/state topics so it can monitor the bridge connection state and also learn which remote broker it’s connected to, since there can be more than one. Ideally there would be a single topic that the client could subscribe to in order to get this information without having to parse all the notifications - see issue #536 - but for now I’m making due with what’s currently available.

While testing using “mosquitto_sub -V mqttv311 -h 127.0.0.1 -t '$SYS/broker/connection/+/state' -t '$SYS/broker/log/N'”, I discovered some inconsistent behavior with the $SYS/broker/log/N topic.

Given the following mosquitto.conf file:

log_dest stderr
log_dest syslog
log_dest topic
log_timestamp true

connection foo
address 192.0.2.1:1883 198.51.100.1:1883
round_robin true
cleansession true
notifications true
bridge_protocol_version mqttv311
start_type automatic
restart_timeout 1
try_private true

Observations:

• If the local mosquitto broker/bridge is started up first, and then mosquitto_sub is started on the same box, mosquitto_sub only receives the state information “1”, but no “Connecting bridge foo (192.0.2.1:1883)” notification message.

• If the local mosquitto broker/bridge is killed and restarted, mosquitto_sub still only receives the state information, but no notification message.

• If the remote broker running on 192.0.2.1 is terminated, then mosquitto_sub receives both state and notification messages as the connection is lost and reestablished on the secondary remote bridge, e.g.:
  0
  1504826652: Connecting bridge foo (198.51.100.1:1883)
  1

• If the remote broker on 192.0.2.1 is restarted and the remote broker on 198.51.100.1 is terminated, then mosquitto_sub again receives both state and notification messages, e.g.:
  0
  1504826801: Connecting bridge foo (192.0.2.1:1883)
  1

• In all cases, the stderr output displays the “Connecting bridge foo (IP:1883)” message; it’s just not always published on the $SYS/broker/log/N topic

Conclusion:
The initial “Connecting bridge foo (IP:1883)” message isn’t being published to the $SYS/broker/log/N topic as one would expect. As far as I can tell from enabling more mosquitto_sub debug using -d, you simply have to assume that following a CONNACK, the first state information received applies to the first IP address in the address list. It would be much nicer if the notification was always published by the broker.

Thanks.

[karlp]

I imagine this is quite simply because log messages aren't published as retained, nor queued for offline subscribers, so you've simply never had the subscriber connected fast enough before the local connection was made. connection/state messages are retained, so whenever your subscriber joins they get them. If you do something like lazy start on the bridge you'd see them turn up.

It's kinda hard to expect to get log messages from startup on the topics when you have to have already started to be able to subscribe to that topic.

[cjmaynard]

Yes, I suppose that's the case. Knowing which remote broker we're connected to is going to be a potential challenge then unless issue #536 can ever be implemented, either as described or by some other mechanism, perhaps even by querying the broker for the current address it's connected to or attempting to connect to.

[cjmaynard]

Since there's likely nothing that can be done to ensure the log message of interest is delivered, I'll close this issue. If issue #536 could be resolved somehow then this problem would become irrelevant anyway.