Octave edge 3.0.2 / 3.10 bug - virtual volatile resource cloud observation fired twice for every single edge action write

[johnofleek]

Use case

An edge action writes some data to a non-volatile virtual resource
There is a cloud observation on the non-volatile virtual resource
The edge action write triggers the cloud observation causing the data to flow to the cloud

The issue
Instead of just one data event flowing to the cloud we see two identical events.

The test
FX30S hardware FW 3.0.2
resource/util/counter is set to count with a 5 second period.
An edge action is triggered from an edge observation on the resource/util/count/value.
When the edge action incoming event count reaches 10 the edge action writes data to resource/virtual/john/test

The following screen grab illustrates the problem

[amons]

Hello John,

retVal[“vr://resource”] = [“waitNonVol”] will create “resource/value” instead of retVal[“vr://resource/value”] = [“waitNonVol”] which creates “resource/value/value”

And it seems that you observe both “resource/value” and “resource/value/value” which might explain why there are two reported values

A.

[johnofleek]

I think you looked at the system when I was making changes - sorry about that - I have since improved the test

There are two edge actions triggered off the counter resource

I’m reasonably confident that

1. The one edge action writes once to the virtual resource and the other edge action writes once to the non-volatile resource
2. The cloud observation on the resource causes 2x cloud stream data events

Our customer originally reported this issue and my code is a test to reproduce the customers problem

The following double cloud events are from the non-volatile write event

The following double cloud events are from the volatile write event

Notice that in both cases the original write timestamp (embedded as as string in the stream payload) are the same but that the arrival timestamp on volatile double cloud events arrive 5 seconds apart.

I have created a new blueprint doubleWriteDoubleobs20201118 you’re welcome to repeat my test.

I’ll leave the system switched on untouched tomorrow

[johnofleek]

Update version FX30S 3.1.0

Using latest test blueprint linkwave “doubleWriteDoubleobs20201123”

The FW 3.1.0 appears to fix the non-volatile event observation but the volatile event observation still fires twice.

The legato log only shows the debug from the two independent vr writes

10:51:48   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:51:48   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:51:48   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":11,\"timestamp\":1606128708.02711}"
10:51:53   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:51:53   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:51:53   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":12,\"timestamp\":1606128713.027904}"
10:51:58   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:51:58   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:51:58   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":13,\"timestamp\":1606128718.027799}"
10:52:03   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:03   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:03   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":14,\"timestamp\":1606128723.026963}"
10:52:08   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:08   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:08   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":15,\"timestamp\":1606128728.027199}"
10:52:13   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:13   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:13   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":16,\"timestamp\":1606128733.026947}"
10:52:18   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:18   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:18   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":17,\"timestamp\":1606128738.027837}"
10:52:23   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:23   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:23   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":18,\"timestamp\":1606128743.027894}"
10:52:28   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:28   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:28   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":19,\"timestamp\":1606128748.026947}"
10:52:33   l5fb7b933d8c3c01d08845e03    xxxxxxxxxx         "nonVol retval = {\"vr://resource\":[\"counter={\\\"value\\\":20,\\\"timestamp\\\":1606128753.0
10:52:33   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         Datahub.read: Failed to read from /app/virtual/john/test/value
10:52:33   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "/virtual/hmi/statem/value not configured yet - could be a reboot"
10:52:33   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":20,\"timestamp\":1606128753.027828}"
10:52:33   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "retval = {\"vr://john/test\":[\"volatile count={\\\"value\\\":20,\\\"timestamp\\\":1606128753.
10:52:38   l5fb7b933d8c3c01d08845e02    xxxxxxxxxx         "volatile ip event ={\"value\":21,\"timestamp\":1606128758.027863}"

But the cloud streams
Volatile 1xWrite 2xCloud

Non-Volatile 1xWrite 1xCVloud