I am stumped as to the best way ensure that my writes to the local device shadow in aws greengrass are successfully delivered to the cloud from the standpoint of a custom component.
Here is my setup:
a) have a custom component, written in python with proper IPC + shadow access policies in place
b) am running the local ShadowManager component to sync a named shadow to the cloud
c) my custom component is writing to the local shadow via the synchronous update_thing_shadow
method on the GreengrassIPCV2 Client.
I can see in my logs that the shadow is successfully posted to the IPC topic and received by ShadowManager:
log statement from greengrass.log when component writes to the local shadow. This does not throw an exception in my custom component.
shadow","contexts":{"service-name":"<my custom component>","thing name":"<thing name>","shadow name":"IotSettings","local-version":"1"},"loggerName":"com.aws.greengrass.shadowmanager.ipc.UpdateThingShadowRequestHandler","timestamp":1689056540672,"cause":null}
Then in greengrass.log, I see this:
{"thread":"pool-2-thread-24","level":"ERROR","eventType":null,"message":"Could not execute cloud shadow get request","contexts":{"thing name":"latest-v3_ET8B4A","shadow name":"IotSettings"},"loggerName":"com.aws.greengrass.shadowmanager.sync.model.BaseSyncRequest","timestamp":1689056542623,"cause":null}
{"thread":"pool-2-thread-24","level":"ERROR","eventType":"sync","message":"Skipping sync request","contexts":{"thing name":"latest-v3_ET8B4A","shadow name":"IotSettings"},"loggerName":"com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy","timestamp":1689056542623,"cause":{"message":"software.amazon.awssdk.services.iotdataplane.model.IotDataPlaneException: null (Service: IotDataPlane, Status Code: 403, Request ID: 2a0fa7c2-d136-66d0-3fa5-31a6afacb1e2)","suppressed":[],"stackTrace":[{"methodName":"getCloudShadowDocument","fileName":"BaseSyncRequest.java","lineNumber":407,"className":"com.aws.greengrass.shadowmanager.sync.model.BaseSyncRequest","nativeMethod":false},{"methodName":"execute","fileName":"FullShadowSyncRequest.java","lineNumber":79,"className":"com.aws.greengrass.shadowmanager.sync.model.FullShadowSyncRequest","nativeMethod":false},{"methodName":"execute","fileName":"MergedFullShadowSyncRequest.java","lineNumber":68,"className":"com.aws.greengrass.shadowmanager.sync.model.MergedFullShadowSyncRequest","nativeMethod":false},{"methodName":"lambda$static$0","fileName":"SyncHandler.java","lineNumber":98,"className":"com.aws.greengrass.shadowmanager.sync.SyncHandler","nativeMethod":false},{"methodName":"runWithRetry","fileName":"RetryUtils.java","lineNumber":50,"className":"com.aws.greengrass.util.RetryUtils","nativeMethod":false},{"methodName":"lambda$static$1","fileName":"SyncHandler.java","lineNumber":96,"className":"com.aws.greengrass.shadowmanager.sync.SyncHandler","nativeMethod":false},{"methodName":"lambda$new$0","fileName":"BaseSyncStrategy.java","lineNumber":155,"className":"com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy","nativeMethod":false},{"methodName":"syncLoop","fileName":"BaseSyncStrategy.java","lineNumber":366,"className":"com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy","nativeMethod":false},{"methodName":"syncLoop","fileName":"RealTimeSyncStrategy.java","lineNumber":77,"className":"com.aws.greengrass.shadowmanager.sync.strategy.RealTimeSyncStrategy","nativeMethod":false},{"methodName":"call","fileName":"Executors.java","lineNumber":511,"className":"java.util.concurrent.Executors$RunnableAdapter","nativeMethod":false},{"methodName":"run","fileName":"FutureTask.java","lineNumber":266,"className":"java.util.concurrent.FutureTask","nativeMethod":false},{"methodName":"runWorker","fileName":"ThreadPoolExecutor.java","lineNumber":1149,"className":"java.util.concurrent.ThreadPoolExecutor","nativeMethod":false},{"methodName":"run","fileName":"ThreadPoolExecutor.java","lineNumber":624,"className":"java.util.concurrent.ThreadPoolExecutor$Worker","nativeMethod":false},{"methodName":"run","fileName":"Thread.java","lineNumber":750,"className":"java.lang.Thread","nativeMethod":false}],"cause":{"message":"null (Service: IotDataPlane, Status Code: 403, Request ID: 2a0fa7c2-d136-66d0-3fa5-31a6afacb1e2)","suppressed":[],"stackTrace":[{"methodName":"handleErrorResponse","fileName":"CombinedResponseHandler.java","lineNumber":125,"className":"software.amazon.awssdk.core.internal.http.CombinedResponseHandler","nativeMethod":false},{"methodName":"handleResponse","fileName":"CombinedResponseHandler.java","lineNumber":82,"className":"software.amazon.awssdk.core.internal.http.CombinedResponseHandler","nativeMethod":false},{"methodName":"handle","fileName":"CombinedResponseHandler.java","lineNumber":60,"className":"software.amazon.awssdk.core.internal.http.CombinedResponseHandler","nativeMethod":false},{"methodName":"handle","fileName":"CombinedResponseHandler.java","lineNumber":41,"className":"software.amazon.awssdk.core.internal.http.CombinedResponseHandler","nativeMethod":false},{"methodName":"execute","fileName":"HandleResponseStage.java","lineNumber":40,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.HandleResponseStage","nativeMethod":false},{"methodName":"execute","fileName":"HandleResponseStage.java","lineNumber":30,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.HandleResponseStage","nativeMethod":false},{"methodName":"execute","fileName":"RequestPipelineBuilder.java","lineNumber":206,"className":"software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallAttemptTimeoutTrackingStage.java","lineNumber":73,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallAttemptTimeoutTrackingStage.java","lineNumber":42,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage","nativeMethod":false},{"methodName":"execute","fileName":"TimeoutExceptionHandlingStage.java","lineNumber":78,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage","nativeMethod":false},{"methodName":"execute","fileName":"TimeoutExceptionHandlingStage.java","lineNumber":40,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallAttemptMetricCollectionStage.java","lineNumber":50,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallAttemptMetricCollectionStage.java","lineNumber":36,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage","nativeMethod":false},{"methodName":"execute","fileName":"RetryableStage.java","lineNumber":81,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage","nativeMethod":false},{"methodName":"execute","fileName":"RetryableStage.java","lineNumber":36,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage","nativeMethod":false},{"methodName":"execute","fileName":"RequestPipelineBuilder.java","lineNumber":206,"className":"software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage","nativeMethod":false},{"methodName":"execute","fileName":"StreamManagingStage.java","lineNumber":56,"className":"software.amazon.awssdk.core.internal.http.StreamManagingStage","nativeMethod":false},{"methodName":"execute","fileName":"StreamManagingStage.java","lineNumber":36,"className":"software.amazon.awssdk.core.internal.http.StreamManagingStage","nativeMethod":false},{"methodName":"executeWithTimer","fileName":"ApiCallTimeoutTrackingStage.java","lineNumber":80,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallTimeoutTrackingStage.java","lineNumber":60,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallTimeoutTrackingStage.java","lineNumber":42,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallMetricCollectionStage.java","lineNumber":48,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage","nativeMethod":false},{"methodName":"execute","fileName":"ApiCallMetricCollectionStage.java","lineNumber":31,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage","nativeMethod":false},{"methodName":"execute","fileName":"RequestPipelineBuilder.java","lineNumber":206,"className":"software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage","nativeMethod":false},{"methodName":"execute","fileName":"RequestPipelineBuilder.java","lineNumber":206,"className":"software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage","nativeMethod":false},{"methodName":"execute","fileName":"ExecutionFailureExceptionReportingStage.java","lineNumber":37,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage","nativeMethod":false},{"methodName":"execute","fileName":"ExecutionFailureExceptionReportingStage.java","lineNumber":26,"className":"software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage","nativeMethod":false},{"methodName":"execute","fileName":"AmazonSyncHttpClient.java","lineNumber":193,"className":"software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl","nativeMethod":false},{"methodName":"invoke","fileName":"BaseSyncClientHandler.java","lineNumber":103,"className":"software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler","nativeMethod":false},{"methodName":"doExecute","fileName":"BaseSyncClientHandler.java","lineNumber":171,"className":"software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler","nativeMethod":false},{"methodName":"lambda$execute$1","fileName":"BaseSyncClientHandler.java","lineNumber":82,"className":"software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler","nativeMethod":false},{"methodName":"measureApiCallSuccess","fileName":"BaseSyncClientHandler.java","lineNumber":179,"className":"software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler","nativeMethod":false},{"methodName":"execute","fileName":"BaseSyncClientHandler.java","lineNumber":76,"className":"software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler","nativeMethod":false},{"methodName":"execute","fileName":"SdkSyncClientHandler.java","lineNumber":45,"className":"software.amazon.awssdk.core.client.handler.SdkSyncClientHandler","nativeMethod":false},{"methodName":"execute","fileName":"AwsSyncClientHandler.java","lineNumber":56,"className":"software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler","nativeMethod":false},{"methodName":"getThingShadow","fileName":"DefaultIotDataPlaneClient.java","lineNumber":221,"className":"software.amazon.awssdk.services.iotdataplane.DefaultIotDataPlaneClient","nativeMethod":false},{"methodName":"getThingShadow","fileName":"IotDataPlaneClientWrapper.java","lineNumber":95,"className":"com.aws.greengrass.shadowmanager.sync.IotDataPlaneClientWrapper","nativeMethod":false},{"methodName":"getCloudShadowDocument","fileName":"BaseSyncRequest.java","lineNumber":374,"className":"com.aws.greengrass.shadowmanager.sync.model.BaseSyncRequest","nativeMethod":false},{"methodName":"execute","fileName":"FullShadowSyncRequest.java","lineNumber":79,"className":"com.aws.greengrass.shadowmanager.sync.model.FullShadowSyncRequest","nativeMethod":false},{"methodName":"execute","fileName":"MergedFullShadowSyncRequest.java","lineNumber":68,"className":"com.aws.greengrass.shadowmanager.sync.model.MergedFullShadowSyncRequest","nativeMethod":false},{"methodName":"lambda$static$0","fileName":"SyncHandler.java","lineNumber":98,"className":"com.aws.greengrass.shadowmanager.sync.SyncHandler","nativeMethod":false},{"methodName":"runWithRetry","fileName":"RetryUtils.java","lineNumber":50,"className":"com.aws.greengrass.util.RetryUtils","nativeMethod":false},{"methodName":"lambda$static$1","fileName":"SyncHandler.java","lineNumber":96,"className":"com.aws.greengrass.shadowmanager.sync.SyncHandler","nativeMethod":false},{"methodName":"lambda$new$0","fileName":"BaseSyncStrategy.java","lineNumber":155,"className":"com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy","nativeMethod":false},{"methodName":"syncLoop","fileName":"BaseSyncStrategy.java","lineNumber":366,"className":"com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy","nativeMethod":false},{"methodName":"syncLoop","fileName":"RealTimeSyncStrategy.java","lineNumber":77,"className":"com.aws.greengrass.shadowmanager.sync.strategy.RealTimeSyncStrategy","nativeMethod":false},{"methodName":"call","fileName":"Executors.java","lineNumber":511,"className":"java.util.concurrent.Executors$RunnableAdapter","nativeMethod":false},{"methodName":"run","fileName":"FutureTask.java","lineNumber":266,"className":"java.util.concurrent.FutureTask","nativeMethod":false},{"methodName":"runWorker","fileName":"ThreadPoolExecutor.java","lineNumber":1149,"className":"java.util.concurrent.ThreadPoolExecutor","nativeMethod":false},{"methodName":"run","fileName":"ThreadPoolExecutor.java","lineNumber":624,"className":"java.util.concurrent.ThreadPoolExecutor$Worker","nativeMethod":false},{"methodName":"run","fileName":"Thread.java","lineNumber":750,"className":"java.lang.Thread","nativeMethod":false}],"cause":null}}}
What I don't understand here is:
a) exactly which authorization is failing (token exchange service does not have credentials yet?)
b) how to ensure that my local shadow update to the shadow hosted in AWS IoT
Specifically on question b, it feels like the component is blind to the failed sync of the shadow between ShadowManager and cloud, and thus does not know that it should retry the write to the shadow.
Versions:
nucleus 2.10.1
shadow manager 2.3.2
I know that my auth policies, etc are correct because the update works most of the time, but there seems to be this race condition between token exchange setup and shadow manager which occurs intermittenly.
Please try to change the policy for GetThingShadow, etc to
*
resource. This can help to understand what the problem is. You can revert this change safely after trying it as a debugging step. Make sure that this policy version is active and attached to the Greengrass core device's certificate.