too many software_list commands are created on tedge-mapper c8y startup when using nanomq about thin-edge.io HOT 10 CLOSED

@didier-wenzek I've added logs to the repository for the individual components, and included the .agent/workflow file after the test was stopped

• https://github.com/thin-edge/debug-tedge-readonly/tree/main/logs/run2

Though the nanomq.log has a lot of error messages, so maybe something is not correct in the nanomq build, as it does not seem to respect the QoS (for unknown reasons).

from thin-edge.io.

Here is a first difference between mosquitto vs nanomq that explains message duplicates:

If a client subscribes to overlapping topic filters (say test/+/xxx and test/xxx/+),
then a message published on the intersection (say on test/xxx/xxx):

• is delivered once to the subscriber by mosquitto
• but is delivered as many as matching subscriptions by nanomq

And indeed the c8y mapper is subscribing to overlapping topic filters:

te/+/+/+/+/cmd/software_list/+
te/+/+/+/+/cmd/software_list
te/device/main///cmd/software_list/+

from thin-edge.io.

Having a look to the log

1. This log is a mix of agent and mapper output.
   That's okay, but it would help to also have the MQTT messages exchange between the two processes.
   I.e. to gather the output of:

   $ tedge mqtt sub 'te/#' &
   $ tedge_mapper_c8y &
   $ tedge_agent &

2. The mapper issued a single software list request c8y-mapper-2024-06-19T18
3. But the agent processed this request 29 times!
4. A weird but a systematic pattern. The request is
   • scheduled once
   • rejected 9 times (because being duplicated)
   • reported as successful (awaiting to be cleared by the mapper)
5. The agent starts by reporting 29 successful requests waiting to be cleared.
   • These requests are resumed on restart
   • Did the mapper failed to acknowledge those during the previous run?
   • Is this number of 29 increasing after each run?
   • It would be good to see the persisted operations in /etc/tedge/.agent/workflows
     (in this specific setting: /data/etc/tedge/.agent/workflows).
6. There are weird rumqttc errors:
   • INFO rumqttc::state: Collision on packet id = 7
   • It would be good to know if on the agent, the mapper or the bridge
7. Harmless:
   • WARN tedge_config::sudo: sudo.enableset totrue, but sudo not found in $PATH

from thin-edge.io.

The agent is persisting (in .agent/workflows) plenty of successful software list requests.

• The agent never received clearing messages for those.
• All these requests have been generated by the mapper in less then a 1 second!

The MQTT log confirms that:

• all the software list requests generated by the mapper are properly executed but never cleared:
  there is no empty retain message published on the te/device/main///cmd/software_list/+ topics.
• All the retain messages are duplicated ad nauseam:
  the mapper reacts to each software update capability by generating a software list request.

from thin-edge.io.

If a client subscribes to overlapping topic filters (say test/+/xxx and test/xxx/+),
then a message published on the intersection (say on test/xxx/xxx):

• is delivered once to the subscriber by mosquitto
• but is delivered as many as matching subscriptions by nanomq

According to the MQTT specs, both behavior are accepted:

it is possible for a Client’s subscriptions to overlap so that a published message might match multiple filters. In this case the Server MUST deliver the message to the Client respecting the maximum QoS of all the matching subscriptions [MQTT-3.3.5-1]. In addition, the Server MAY deliver further copies of the message, one for each additional matching subscription and respecting the subscription’s QoS in each case.

from thin-edge.io.

The latest version of NanoMQ has an incorrect behavior when a client has several subscriptions.
It incorrectly delivers a copy of the message for each subscription even if unrelated :

$ docker run -d --name nanomq -p 1883:1883 -p 8083:8083 -p 8883:8883 emqx/nanomq:latest
$ mosquitto_pub -r -t sport -m tennis
$ mosquitto_sub -t sport
tennis
^C
$ mosquitto_sub -t unrelated
^C
$ mosquitto_sub -t sport -t unrelated
tennis
tennis
^C

from thin-edge.io.

A ticket has been created in the nanomq, nanomq/nanomq#1817, where it seems there was a recent change that introduced this erroneous behaviour for retained messages

from thin-edge.io.

Sorry to break this. 0.22.0 is a beta release, hopefully I didn't make too much trouble for you

from thin-edge.io.

Sorry to break this. 0.22.0 is a beta release, hopefully we I didn't make too much trouble for you

All good. We actually stumbled across it as we were building a static binary from the main branch…it took us a while to find out the reason for the unexpected behaviour, but glad we’re able to help identify the issue in the end.

from thin-edge.io.

QA tested the bug and it is not reproducable, creating test case to cover this bug is in progress

from thin-edge.io.