Shadow Manager Sync Out of Order

0

Intro

Using greengrass V2
aws.greengrass.ShadowManager v2.2.1
aws.greengrass.Nucleus v2.7.0
I built a custom component that talks to the shadowManager to update the device shadow. The shadowManager is configured as follow:

{
   "strategy":{
      "type":"realTime"
   },
   "synchronize":{
      "coreThing":{
         "classic":true,
         "namedShadows":[
            "notRelevant"
         ]
      },
      "direction":"betweenDeviceAndCloud"
   }
}

The problem

My custom component attempts to do the following:

  1. Subscribe to $aws/things/my_thing/shadow/delta/update with callback function.
  2. Update device's reported values to some default values that's different from the desired values in the IoT Core.
  3. The update in step 2 triggers the callback in step 1, which updates device's reported values with the desired values.

I would expect the cloud to have matching desired and reported values at the end, but ended up with the default values inreported, like so: IoT Core Console Where transmit_rate 15 and sample_rate 2.5 are the default values and the transmit_rate 10 and sample_rate 1 are the desired.

What I found

I checked our application software log and confirmed that two shadow update requests were made and accepted by the ShadowManager. The first one updates the shadow to default values, and the second updates it to the desired values.

Then, I checked greengrass.log and saw that the Updating sync info logs highlighted seems to suggest that the two updates are synced in reserve order (version 278 first, with version 277 following). This appears to be highly correlated to the out-of-sync problem described above. Enter image description here

I was able to mitigate this problem by introducing a 1 second delay between the two update requests. This tells me that the problem might have to do with timing/synchronization within the ShadowManager or the Greengrass Core software.

Does anyone have better idea on what the root cause can be?

Thanks,

---Edits ---

Adding a log from my custom component software to show the response from ShadowManager (highlighted)

  • the log on 09:26:00,112 is the response for my first UpdateThingShadowRequest
  • the next log on 09:26:00,112 is the update/delta shadow I received in the callback.
  • the log on 09:26:00,122 is the response for my second UpdateThingShadowRequest

Enter image description here

  • Hey ictwist,

    I have a few questions regarding what your component is doing to better understand your situation, given it is hard to tell how your application is structured with just the provided details:

    You mention "Update device's reported values to some default values that's different from the desired values in the IoT Core.".

    1. Does this mean you are starting by changing the Device Shadow document on IoT core through the aws console to some reported value or your custom component is changing the "reported" values, how are you doing this, what is the payload you are sending?

    2. Also you mention "the two updates are synced" so I am imagine either your custom component is sending 2 updates or is it that you start with a specific document value on the cloud and then when your component starts it tries to set it to something else? - Please provide more details about what your component is sending and what you are doing here

  • ochoanel,

    Thanks for helping me to clarify:

    1. My custom component is changing the "reported" values, I'm doing this by creating an UpdateThingShadowRequest with the payload of
    {
       "state":{
          "reported":{
             "sample_rate":2.5,
             "transmit_rate":15
          }
       }
    }
    
    1. My custom component is sending 2 updates. The first update is described above, the second update is a part of the callback, which is trigger by the first update, because the first update changes the value of $aws/things/my_thing/shadow/delta/update
  • What is the payload you are sending on your second request. I imagine you are calling UpdateThingShadowRequest, as you mentioned, after you get a call to the callback you registered on $aws/things/my_thing/shadow/delta/update. Also just to double check, you are not manually modifying the document on the aws console correct? - Sorry for all the questions, just want to get the full picture to check if I can reproduce it myself and see what is going on.

    From the log picture you provided I can see the requests are being processed by different threads so it is possible that there might be a synchronization issue.

  • Yes the second update is also done through UpdateThingShadowRequest and the payload is this

    {
       "state":{
          "reported":{
             "sample_rate":1,
             "transmit_rate":10
          }
       }
    }
    

    You are correct that this request is triggered by the callback I registered on $aws/things/my_thing/shadow/delta/update

    Since I can't figure out how to add image in comments, please see the edit part of my original post for additional log from my custom component that includes the responses from ShadowManager from my 2 UpdateThingShadowRequestcalls.

ictwist
asked 2 years ago287 views
1 Answer
0
Accepted Answer

Hi ictwist, By your description, this issue can be mitigated by setting some delay. It seems like this is highly related to a possible bug in ShadowManager. We have marked it in our backlog to further verify and fix it. Thanks for your report.

AWS
Daojing
answered 2 years ago

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.

Guidelines for Answering Questions