duplicate device registration messages when using tedge-log-plugin as a child device #2389

reubenmiller · 2023-10-30T23:12:37Z

Describe the bug

A child device is being registered twice under two different topic names which results in operation sent from Cumulocity not being mapped to the correct te/ topic (or at least not the topic which is being listened to by the "child-device").

The error was discovered during updates to the tedge-demo-container@feat-te-as-child-device project which uses the following container setup:

container 1: mosquitto
container 2: main device (with the mapper, tedge-agent, tedge-configuration-plugin, tedge-log-plugin etc.)
container 3: child device (with tedge-agent, tedge-configuration-plugin, tedge-log-plugin)

Once the child device container starts up, two te/ registration messages for the same @id are present but on different local te topics. An example of the two duplicated registration messages are shown below:

[te/device/child01//] {"@id":"test_20231030_03:device:child01","@type":"child-device","name":"child01"}
[te/device/test_20231030_03:device:child01//] {"@id":"test_20231030_03:device:child01","@type":"child-device","name":"test_20231030_03:device:child01"}

The error seems to be caused when the tedge-log-plugin component is registered as a child device when the tedge-mapper-c8y is not running. When the mapper starts, it creates the erroneous te/device/<child-id>// registration message.

To Reproduce

Given a main device with thin-edge.io connected to Cumulocity IoT, run the following steps:

Open a console and stop the tedge-mapper-c8y service
```
sudo systemctl stop tedge-mapper-c8y
```
In a new console, start the tedge-log-plugin as a child device
```
tedge-log-plugin --mqtt-device-topic-id device/child1//
```
Go to the previous console, and start the mapper
```
sudo systemctl start tedge-mapper-c8y
```

Check the registration messages

tedge mqtt sub 'te/+/+/+/+'

Inspect the registration messages, and there should NOT be duplicated registration messages for the child1 device for different te/device/<child-id>// topics:

[te/device/child1//] {"@id":"poppy:device:child1","@type":"child-device","name":"child1"}
[te/device/poppy:device:child1//] {"@id":"poppy:device:child1","@type":"child-device","name":"poppy:device:child1"}

Expected behavior

When using thin-edge.io as a child device, it should only register the @id of the device under one topic on startup, and that topic should be the same as the configured mqtt.device_topic_id setting in the /etc/tedge/tedge.toml.

For example, if mqtt.device_topic_id is set to device/child01//, then the topic should be:

te/device/child01//

And there should not be a second registration message sent to a topic with this pattern:

te/device/test_20231030_03:device:child01//

Screenshots

Environment (please complete the following information):

OS [incl. version]: alpine linux 3.18
Hardware [incl. revision]: docker
System-Architecture [e.g. result of "uname -a"]: aarch64
thin-edge.io version [e.g. 0.1.0]: 0.12.1~513+g8edcba2

Additional context

The text was updated successfully, but these errors were encountered:

Signed-off-by: Reuben Miller <reuben.d.miller@gmail.com>

reubenmiller · 2023-10-31T09:07:42Z

Doing some further investigations and it seems to be a problem just in the tedge-log-plugin. I ran the test again but isolated single binaries (e.g. only tedge-agent, or only tedge-log-plugin) to check which component is causing the error:

Only using tedge-log-plugin - FAIL

[te/device/child01/service/tedge-log-plugin] {"@parent":"device/child01//","@type":"service","type":"service"}
[te/device/child01/service/tedge-log-plugin/status/health] {"pid":161,"status":"up","time":"2023-10-31T09:01:54.066112816Z"}
[te/device/child01///cmd/log_upload] {"types":["shell","software-management"]}
[te/device/child01//] {"@id":"test_20231031_16:device:child01","@type":"child-device","name":"child01"}
[te/device/test_20231031_16:device:child01//] {"@id":"test_20231031_16:device:child01","@type":"child-device","name":"test_20231031_16:device:child01"}

It is possible that the registration of the log_upload capability via te/device/child01///cmd/log_upload is done before the child device registration te/device/child01// is causing some issues?

Only using tedge-configuration-plugin - OK

[te/device/child01/service/tedge-configuration-plugin] {"@parent":"device/child01//","@type":"service","type":"service"}
[te/device/child01/service/tedge-configuration-plugin/status/health] {"pid":172,"status":"up","time":"2023-10-31T08:53:10.634069192Z"}
[te/device/child01//] {"@id":"test_20231031_13:device:child01","@type":"child-device","name":"child01"}
[te/device/child01///cmd/config_snapshot] {"types":["system.toml","tedge-configuration-plugin","tedge.toml"]}
[te/device/child01///cmd/config_update] {"types":["system.toml","tedge-configuration-plugin","tedge.toml"]}

Only using tedge-agent - OK

[te/device/child01/service/tedge-agent] {"@id":"test_20231031_14:device:child01:service:tedge-agent","@parent":"device/child01//","@type":"service","name":"tedge-agent","type":"service"}
[te/device/child01/service/tedge-agent/status/health] {"pid":163,"status":"up","time":"2023-10-31T08:57:56.671546286Z"}
[te/device/child01//] {"@id":"test_20231031_14:device:child01","@type":"child-device","name":"child01"}
[te/device/child01///cmd/restart] {}
[te/device/child01///cmd/software_list] {}
[te/device/child01///cmd/software_list/cQD96Q27EjnuojkrGf6CI] {"status":"executing"}
[te/device/child01///cmd/software_update] {}

reubenmiller · 2023-10-31T09:25:30Z

I've found an easier way to reproduce the bug, I'll update the ticket description

albinsuresh · 2023-10-31T13:04:51Z

It is possible that the registration of the log_upload capability via te/device/child01///cmd/log_upload is done before the child device registration te/device/child01// is causing some issues?

That was my first assumption as well, but this isn't the case here. It is another message race during the startup. The child device list sync mechanism of the mapper, during its startup, where it looks at the differences between the child device list received from the cloud vs the ones known locally, and any new local ones are registered with the cloud is what's triggering that duplicate registration message. Here is the message race that's happening:

The mapper on restart requests the child device list from the cloud
The cloud sends an empty child list response, as no child devices are registered yet (the log plugin registration, which creates the child device, is not processed by the mapper yet).
While the cloud response(empty child list) is in transit, the mapper processes the log plugin capability message, auto-registering the child device and the service in that process. This step creates the test_20231030_03:device:child01 child directory under /etc/tedge/operations/c8y.
Then it receives the empty child list from the cloud, as that was sent from the cloud before the child device was registered in the previous step.
When the mapper receives the empty child list, it tries register that child device named test_20231030_03:device:child01 found in the operations directory once more.

I'll update this ticket with the fix approach, once I work out something.

reubenmiller · 2023-10-31T13:16:37Z

@albinsuresh Though are you sure that sending the child-device registration message first before any operation registration messages wouldn't fix the situation? Or is it just by chance that I didn't see this error on other components (e.g. tedge-configuration-plugin, tedge-agent etc.)?

reubenmiller · 2023-10-31T13:26:15Z

After further testing it seems to affect all components when running as a child-device.

When starting the following components with different child ids and the tedge-mapper-c8y is stopped, it results in 3 erroneous device registration messages:

TEDGE_RUN_LOCK_FILES=false tedge-agent --mqtt-device-topic-id device/child1//
tedge-configuration-plugin --mqtt-device-topic-id device/child2//
tedge-log-plugin --mqtt-device-topic-id device/child3//

If the child device directory the child device operation directories follow the default external id naming scheme, they are auto-registered with the right topic id and name derived from that external id.

…tory-registration Fix auto-registration of child device op dirs #2389

reubenmiller · 2023-10-31T18:31:00Z

Merged PR to address the incorrect registration of the child devices.

Add systems tests here:

device_registration.robot#L130

reubenmiller · 2023-11-01T11:05:05Z

QA has thoroughly checked the feature and here are the results:

Test for ticket exists in the test suite.
QA has tested the bug and could not reproduce it anymore.

reubenmiller added the bug Something isn't working label Oct 30, 2023

reubenmiller added a commit to thin-edge/tedge-demo-container that referenced this issue Oct 30, 2023

add workaround for thin-edge/thin-edge.io#2389

d85422e

Signed-off-by: Reuben Miller <reuben.d.miller@gmail.com>

reubenmiller changed the title ~~duplicate device registration messages resulting when using thin-edge.io as a child device~~ duplicate device registration messages when using tedge-log-plugin as a child device Oct 31, 2023

rina23q assigned albinsuresh Oct 31, 2023

This was referenced Oct 31, 2023

Fix auto-registration of child device op dirs #2389 #2393

Merged

run tedge-mapper-c8y in an independent container thin-edge/tedge-demo-container#50

Merged

reubenmiller added this to the 0.13.0 milestone Oct 31, 2023

reubenmiller added a commit that referenced this issue Oct 31, 2023

Merge pull request #2393 from albinsuresh/fix/2389/fix-child-op-direc…

180681b

…tory-registration Fix auto-registration of child device op dirs #2389

reubenmiller unassigned albinsuresh Oct 31, 2023

reubenmiller self-assigned this Nov 1, 2023

reubenmiller closed this as completed Nov 1, 2023

This was referenced Nov 2, 2023

Add certificate based authentication to c8y-auth-proxy #2397

Closed

Add HTTPS/TLS support to the auth proxy #2430

Merged

This was referenced Nov 29, 2023

Get operation from JSON over MQTT instead of SmartREST #2482

Merged

Ordered processing of entity registration messages before any other messages #2466

Merged

github-actions bot mentioned this issue Dec 14, 2023

Make entity store persistent #2428 #2522

Merged

11 tasks

This was referenced Jan 9, 2024

chore: update system test dependencies #2577

Merged

Only send 114 when operations changed #2588

Merged

github-actions bot mentioned this issue Feb 23, 2024

Add support for built-in bridge to tedge-mapper-c8y #2716

Merged

11 tasks

github-actions bot mentioned this issue Mar 18, 2024

fix: Honor c8y.mqtt setting on tedge connect #2789

Merged

13 tasks

This was referenced May 13, 2024

Support Cumulocity Device Availability #2866

Closed

test: Fix remaining test failures from built-in bridge #2879

Merged

This was referenced Jun 19, 2024

feat: support c8y device availability feature #2940

Merged

feat: use loopback ip address instead of alias to improve compatibility #2952

Merged

This was referenced Jul 5, 2024

chore(deps): Bump crate-ci/typos from 1.22.3 to 1.23.0 #2976

Closed

tests: improve debugging of bootstrap script and include systemd/cgroup compat check #2981

Merged

github-actions bot mentioned this issue Jul 18, 2024

feat: use direct c8y connection for c8y-remote-access-plugin #3006

Merged

11 tasks

github-actions bot mentioned this issue Aug 19, 2024

Add AWS keywords and create test for connecting thinedge to AWS using keys for authentication #3066

Closed

11 tasks

github-actions bot mentioned this issue Nov 10, 2024

fix: Don't fail if only some operations could not be loaded #3236

Merged

16 tasks

github-actions bot mentioned this issue Dec 5, 2024

feat: Entity registration HTTP API #3230

Open

20 tasks

github-actions bot mentioned this issue Jan 10, 2025

feat: audit journal of commands and trace of actor messages #3325

Draft

11 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

duplicate device registration messages when using tedge-log-plugin as a child device #2389

duplicate device registration messages when using tedge-log-plugin as a child device #2389

reubenmiller commented Oct 30, 2023 •

edited

Loading

reubenmiller commented Oct 31, 2023 •

edited

Loading

reubenmiller commented Oct 31, 2023

albinsuresh commented Oct 31, 2023 •

edited

Loading

reubenmiller commented Oct 31, 2023

reubenmiller commented Oct 31, 2023

reubenmiller commented Oct 31, 2023 •

edited

Loading

reubenmiller commented Nov 1, 2023

duplicate device registration messages when using tedge-log-plugin as a child device #2389

duplicate device registration messages when using tedge-log-plugin as a child device #2389

Comments

reubenmiller commented Oct 30, 2023 • edited Loading

reubenmiller commented Oct 31, 2023 • edited Loading

reubenmiller commented Oct 31, 2023

albinsuresh commented Oct 31, 2023 • edited Loading

reubenmiller commented Oct 31, 2023

reubenmiller commented Oct 31, 2023

reubenmiller commented Oct 31, 2023 • edited Loading

reubenmiller commented Nov 1, 2023

reubenmiller commented Oct 30, 2023 •

edited

Loading

reubenmiller commented Oct 31, 2023 •

edited

Loading

albinsuresh commented Oct 31, 2023 •

edited

Loading

reubenmiller commented Oct 31, 2023 •

edited

Loading