(shadow manager): starts doing a full resync every second

[crispinboylan-int]

Describe the bug A clear and concise description of what the bug is.

Occasionally the shadow manager will go into a mode where it starts resyncing the shadows every second. This sends cloud costs spiralling.

log entries:

2023-01-06T11:00:01.263Z [WARN] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection interrupted. {clientId=xxx, error=The connection was closed unexpectedly.} 2023-01-06T11:00:01.263Z [INFO] (Thread-3) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Stop syncing. {} 2023-01-06T11:00:01.263Z [INFO] (Thread-3) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Cancel 1 sync thread(s). {} 2023-01-06T11:00:01.263Z [WARN] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Interrupted while waiting for sync requests. {} 2023-01-06T11:00:01.263Z [INFO] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Finished processing sync requests. {} 2023-01-06T11:00:01.364Z [INFO] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection resumed. {clientId=xxx, sessionPresent=true} 2023-01-06T11:00:01.364Z [INFO] (Thread-3) com.aws.greengrass.shadowmanager.sync.strategy.RealTimeSyncStrategy: sync. Start real time syncing. {} 2023-01-06T11:00:01.364Z [INFO] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Start processing sync requests. {} 2023-01-06T11:00:01.365Z [INFO] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=FullShadowSyncRequest, thing name=xxx, shadow name=AirQuality} 2023-01-06T11:00:01.367Z [INFO] (Thread-3) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=RECONNECT, serviceName=FleetStatusService, currentState=RUNNING} 2023-01-06T11:00:01.367Z [INFO] (Thread-3) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=RECONNECT, serviceName=FleetStatusService, currentState=RUNNING} 2023-01-06T11:00:01.384Z [INFO] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=FullShadowSyncRequest, thing name=xxx, shadow name=Climate} 2023-01-06T11:00:01.399Z [INFO] (pool-2-thread-11524) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=FullShadowSyncRequest, thing name=xxx, shadow name=CommandConfig}

To Reproduce Seems to happen intermittently

Expected behavior Normal syncing behaviour

Actual behavior Resyncing every second or so continuously

Environment

• OS: ubuntu 22.04
• JDK version: 17
• Nucleus version: 2.7.0
• Shadow Manager version: 2.2.4

Additional context goes back to normal after restart of greengrass service.

[crispinboylan-int]

greengrass_2023_01_06_11_0.log.resync.gz

attaching a full log.

[saranyailla]

Hi, From the logs you shared, we can see that the MQTT connection got interrupted and resumed intermittently. Whenever the MQTT connection is interrupted, shadow manager component stops syncing all the shadows and when the connection resumes again, it starts syncing all the shadows (Link to the code). So, shadow manager behavior is correct here.

You mentioned that the issue got resolved after restarting the Greengrass. So, could you please check on your end why the MQTT connection is interrupted and resumed multiple times and is stable after greengrass restarts? Please check AWS IoT CloudWatch logs to see if there are duplicate client IDs or permission issues that are causing this.

[crispinboylan-int]

it seems to me this happens soon after a deploy from greengrass. the deploy completes successfully but a short time after this disconnection starts happening and keeps happening until greengrass is manually restarted, after which all is fine.

it seems random as to which devices it affects, e.g. we deploy to 25 devices and on 3 this starts happening, despite the fact that all devices are identically configured.

[crispinboylan-int]

this is what I see in the logs around the time it starts happening:

2023-01-12T13:43:05.129Z [INFO] (pool-2-thread-49) com.aws.greengrass.deployment.IotJobsHelper: Updating status of persisted deployment. {Status=SUCCEEDED, StatusDetails={detailed-deployment-status=SUCCESSFUL}, ThingName=home-0U5Ia8Rfl8TS, JobId=3d8ee212-28a7-4cc0-bd7d-c597365c4ccf} 2023-01-12T13:43:05.131Z [INFO] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection purposefully interrupted. {clientId=home-0U5Ia8Rfl8TS#2} 2023-01-12T13:43:05.184Z [INFO] (pool-2-thread-49) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-01-12T13:43:16.291Z [INFO] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-01-12T13:43:16.291Z [INFO] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection purposefully interrupted. {clientId=home-0U5Ia8Rfl8TS#2} 2023-01-12T13:43:16.374Z [INFO] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Successfully connected to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2, sessionPresent=false} 2023-01-12T13:43:16.412Z [INFO] (pool-2-thread-30) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-01-12T13:43:16.495Z [WARN] (Thread-3) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection interrupted. {clientId=home-0U5Ia8Rfl8TS#2, error=The connection was closed unexpectedly.

To get this I had to try the deploy twice, once it was fine, the next time this started happening - even though there was no change in any components between the deploys.

[MikeDombo]

Hi @crispinboylan-int,

Please enable AWS IoT CloudWatch logs: https://docs.aws.amazon.com/iot/latest/developerguide/cloud-watch-logs.html. These logs in the AWS Console will tell you why the connection is being closed by AWS.

[crispinboylan-int]

yes I see:

{ "timestamp": "2023-01-12 13:59:29.996", "logLevel": "ERROR", "traceId": "009f15fc-f7ce-262b-0d81-f99a3267c11a", "accountId": "XXX", "status": "Failure", "eventType": "Disconnect", "protocol": "MQTT", "clientId": "home-0U5Ia8Rfl8TS#2", "principalId": "dcd65e88fea0fb0aa1d62a7f420d47dd6434494225aaf6d0557f6b9f2b4217e0", "sourceIp": "xxx", "sourcePort": 49456, "reason": "DUPLICATE_CLIENT_ID", "details": "A new connection was established with the same client ID", "disconnectReason": "DUPLICATE_CLIENTID" }

[MikeDombo]

OK then. This explains the issue then. Are you running an MQTT client with that client ID yourself on that device or any other device?

[MikeDombo]

Please use Nucleus 2.8.1 or newer. 2.8.1 fixed an issue when handling more than one MQTT connection which may be related to what you are experiencing.

[crispinboylan-int]

no we're not, we only connect via greengrasscoreipc client to the core device.

but why would deploys trigger the issue (even when no components are changed or restarted)?

[MikeDombo]

Deployments require additional MQTT subscriptions to operate. Between your shadow subscriptions and base subscriptions, you must be exceeding 50 subscriptions which then spawns a new MQTT connection. AWS IoT Core limits connections to 50 subscriptions.

[crispinboylan-int]

many thanks, we have not had this issue since upgrading to 2.9.2.

[crispinboylan-int]

have had this issue now on 2.9.2.

[crispinboylan-int]

seems to occur less frequently that when on 2.7.0, around every 2 minutes the connection drops and is re-established. The error in the IOT logs is the same - duplicate client id.

[crispinboylan-int]

i also seem to see this error in the logs:

{ "timestamp": "2023-01-30 16:52:54.919", "logLevel": "ERROR", "traceId": "679c7780-e840-bcb3-960d-fbdfda8b0ec4", "accountId": "XXX", "status": "Failure", "eventType": "GetThingShadow", "protocol": "MQTT", "deviceShadowName": "home-XXXX", "topicName": "$aws/things/home-XXXX/shadow/name/AWSManagedGreengrassV2Deployment/get", "details": "No shadow exists with name: 'home-XXXX~AWSManagedGreengrassV2Deployment'" }

[MikeDombo]

This issue should be fixed by https://github.com/aws-greengrass/aws-greengrass-nucleus/pull/1389. You should be seeing this issue when changing the shadow manager configuration over time (more specifically, removing some shadows and possibly adding them back later). If you set it once and just leave it, it should then work fine. Restarting Greengrass on the device should also resolve it if the root cause is correct.

The "error" about the deployment shadow not existing isn't a problem.

We are working to release the linked fix soon.

[crispinboylan-int]

thanks for the update - restarting does indeed resolve the issue. But i'm not changing any of the shadow manager config here, its the same between deployments. Simply doing the deploy seems to provoke the issue.

[MikeDombo]

What is the full value of the configuration update of Shadow Manager in your deployment (including "merge" and "reset")?

[crispinboylan-int]

    "aws.greengrass.ShadowManager": {
        "componentVersion": "2.2.4",
        "configurationUpdate": {
            "merge": "{\"shadowDocumentSizeLimitBytes\":30720,\"synchronize\":{\"coreThing\":{\"classic\":false,\"namedShadows\":[\"Climate\",\"Lighting\",\"Shading\",\"AirQuality\",\"Energy\",\"Presets\",\"OperatorRules0\",\"OperatorRules1\",\"OperatorRules2\",\"OperatorRules3\",\"OperatorRules4\",\"OperatorRules5\",\"OperatorRules6\",\"OperatorRules7\",\"CommandConfig\",\"SubscriptionConfig\",\"RoomConfig\",\"RoomConfig1\",\"RoomConfig2\",\"RoomConfig3\",\"UnitConfig\"]}}}"
        }
    },

[MikeDombo]

Enabling Greengrass debug logs will help to validate the root cause.

"aws.greengrass.Nucleus": {
        "componentVersion": "2.9.2",
        "configurationUpdate": {
            "merge": "{\"logging\": {\"level\": \"DEBUG\"}}"
        }
    },

What I would expect to see is logs that say "Unsubscribed to " and "Subscribed to ".

After restarting Greengrass and things are working correctly, how many deployments does it take before it starts misbehaving?

[crispinboylan-int]

i think around 2 or 3 deployments usually, I dont see any logs of "Unsubscribed to/Subscribed to" but what I see around the connection interrupted messages is:

2023-01-31T17:49:53.456Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain: Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.core.internal.interceptor.HttpChecksumRequiredInterceptor@15f73c86, software.amazon.awssdk.core.internal.interceptor.SyncHttpChecksumInTrailerInterceptor@5606c899, software.amazon.awssdk.core.internal.interceptor.HttpChecksumValidationInterceptor@2d53bc07, software.amazon.awssdk.core.internal.interceptor.AsyncRequestBodyHttpChecksumTrailerInterceptor@2acfcac3, software.amazon.awssdk.core.internal.interceptor.HttpChecksumInHeaderInterceptor@670c010, software.amazon.awssdk.awscore.interceptor.HelpfulUnknownHostExceptionInterceptor@66d28247, software.amazon.awssdk.awscore.eventstream.EventStreamInitialRequestInterceptor@5651a91e, software.amazon.awssdk.awscore.interceptor.TraceIdExecutionInterceptor@21cf8c5]. {} 2023-01-31T17:49:53.465Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.request: Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=https, host=logs.eu-west-2.amazonaws.com, encodedPath=/, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent, X-Amz-Target, x-amzn-logs-format], queryParameters=[]). {} 2023-01-31T17:49:53.470Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.core.internal.io.SdkLengthAwareInputStream: Specified InputStream length of 1101625 has been reached. Returning EOF.. {} 2023-01-31T17:49:53.470Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.auth.signer.Aws4Signer: AWS4 String to sign: AWS4-HMAC-SHA256 20230131T174953Z 20230131/eu-west-2/logs/aws4_request 01caea86ea171de3b52359144493e7e3c26afab58030513ae2187c6a9a48ade8. {} 2023-01-31T17:49:53.470Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of logs.eu-west-2.amazonaws.com/52.94.57.200:443. {} 2023-01-31T17:49:53.471Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of logs.eu-west-2.amazonaws.com/52.94.57.200:443. {} 2023-01-31T17:49:53.471Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing logs.eu-west-2.amazonaws.com/52.94.57.200:443. {} 2023-01-31T17:49:53.474Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.http.apache.internal.conn.SdkTlsSocketFactory: socket.getSupportedProtocols(): [TLSv1.3, TLSv1.2, TLSv1.1, TLSv1, SSLv3, SSLv2Hello], socket.getEnabledProtocols(): [TLSv1.3, TLSv1.2]. {} 2023-01-31T17:49:53.482Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: created: logs.eu-west-2.amazonaws.com/52.94.57.200:443. {} 2023-01-31T17:49:53.588Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.requestId: Received successful response: 200, Request ID: cbe62bab-781c-4095-adf4-36618f8c75c1, Extended Request ID: not available. {} 2023-01-31T17:49:53.589Z [DEBUG] (pool-2-thread-40) software.amazon.awssdk.request: Received successful response: 200, Request ID: cbe62bab-781c-4095-adf4-36618f8c75c1, Extended Request ID: not available. {} 2023-01-31T17:50:06.229Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.229Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.229Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.229Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.229Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.230Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.231Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/35.176.132.58:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/18.133.148.80:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/18.133.148.80:443. {} 2023-01-31T17:50:06.232Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com/18.133.148.80:443. {}

2023-01-31T17:50:09.565Z [DEBUG] (pool-1-thread-4) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $local/greengrass/telemetry. {componentName=aws.greengrass.telemetry.NucleusEmitter} 2023-01-31T17:50:09.568Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.568Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.568Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.568Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.569Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.569Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.569Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.569Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.570Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.570Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.570Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.570Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.571Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.571Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.571Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.571Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.572Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.572Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.572Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.572Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.576Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.576Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.576Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.577Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302220286320. {} 2023-01-31T17:50:09.577Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.577Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.577Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.578Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.578Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.578Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.578Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.578Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.579Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.579Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.579Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.579Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.580Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.580Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.580Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.580Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.582Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.582Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatch/metric/put. {} 2023-01-31T17:50:09.582Z [DEBUG] (Thread-7) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic cloudwatch/metric/put. {componentName=co.mgh.CoreMetricsForwarder} 2023-01-31T17:50:09.582Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:09.583Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: Continuation native id: 140302221783888. {} 2023-01-31T17:50:09.583Z [DEBUG] (Thread-7) com.aws.greengrass.authorization.AuthorizationHandler: Hit policy with principal co.mgh.CoreMetricsForwarder, operation aws.greengrass#PublishToTopic, resource cloudwatc 2023-01-31T17:50:09.584Z [INFO] (pool-1-thread-2) com.aws.greengrass.detector.IpDetectorManager: Acquired host IP addresses. {IpAddresses=[/172.18.0.1, /10.0.10.50]} 2023-01-31T17:50:09.585Z [DEBUG] (Thread-7) software.amazon.awssdk.eventstreamrpc.OperationContinuationHandler: aws.greengrass#PublishToTopic stream continuation closed.. {} 2023-01-31T17:50:11.565Z [WARN] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection interrupted. {clientId=XXXX#2, error=The connection was closed unexpectedly.} 2023-01-31T17:50:11.566Z [INFO] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Stop syncing. {} 2023-01-31T17:50:11.566Z [INFO] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Cancel 1 sync thread(s). {} 2023-01-31T17:50:11.566Z [WARN] (pool-2-thread-597) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Interrupted while waiting for sync requests. {} 2023-01-31T17:50:11.566Z [INFO] (pool-2-thread-597) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Finished processing sync requests. {} 2023-01-31T17:50:11.622Z [INFO] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection resumed. {clientId=XXXX#2, sessionPresent=true} 2023-01-31T17:50:11.622Z [INFO] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.RealTimeSyncStrategy: sync. Start real time syncing. {} 2023-01-31T17:50:11.623Z [INFO] (pool-2-thread-597) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Start processing sync requests. {} 2023-01-31T17:50:11.623Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Adding new sync request. {thing name=XXXX, shadow name=AirQuality, type=class com.aws.greengrass.shadowmanager.sync.model.FullShadowSyncRequest} 2023-01-31T17:50:11.623Z [INFO] (pool-2-thread-597) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=FullShadowSyncRequest, thing name=XXXX, shadow name=AirQuality} 2023-01-31T17:50:11.624Z [DEBUG] (pool-2-thread-597) software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain: Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.core.internal.interceptor.HttpChecksumRequiredInterceptor@31d72ee8, software.amazon.awssdk.core.internal.interceptor.SyncHttpChecksumInTrailerInterceptor@21d5f097, software.amazon.awssdk.core.internal.interceptor.HttpChecksumValidationInterceptor@539afec9, software.amazon.awssdk.core.internal.interceptor.AsyncRequestBodyHttpChecksumTrailerInterceptor@4f7653c9, software.amazon.awssdk.core.internal.interceptor.HttpChecksumInHeaderInterceptor@47de94a1, software.amazon.awssdk.awscore.interceptor.HelpfulUnknownHostExceptionInterceptor@49018585, software.amazon.awssdk.awscore.eventstream.EventStreamInitialRequestInterceptor@4de946da, software.amazon.awssdk.awscore.interceptor.TraceIdExecutionInterceptor@30fcbcb5]. {} 2023-01-31T17:50:11.624Z [DEBUG] (pool-2-thread-597) software.amazon.awssdk.request: Sending Request: DefaultSdkHttpFullRequest(httpMethod=GET, protocol=https, host=a3f5s93gy9cwkb-ats.iot.eu-west-2.amazonaws.com, encodedPath=/things/XXXX/shadow, headers=[amz-sdk-invocation-id, User-Agent], queryParameters=[name]). {}

[MikeDombo]

Most likely the subscribe/unsubscribe will be before those logs. Use grep or another tool to search for Subscribed to and Unsubscribed to

[crispinboylan-int]

i'm logging to cloudwatch and not seeing either of these messages when searching either there or locally in the files

[MikeDombo]

Can you search for Successfully connected to AWS IoT Core? This will show where the MQTT connection is initially created, particularly we're interested in the clientID ending with #2 since that's the one which is being duplicated. I'd like to know given the logs near "Successfully connected to AWS IoT Core" what Greengrass was doing which caused it to create the new client.

[crispinboylan-int]

sure, please see logs_conn.txt

[MikeDombo]

At 2023-01-31T17:46:16.623Z, a new connection is made with the #2 client with the log line Getting new MQTT connection. That client then immediately disconnects, presumably due to the duplicate client ID. However, that's the first instance in the log that you provided which shows a client with that ID being created.

Are there logs from before 17:46 which have the same log text "Getting new MQTT connection. {clientId=home-XXXX#2}"?

Looking at the AWS IoT CloudWatch logs, is the reason for disconnection still "duplicate client id"? If so, from those same logs, when did the client ID #2 first connect? In those logs, is there a client connected with client ID #3?

[crispinboylan-int]

I see these instances:

2023-01-31T17:33:22.051Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2} 2023-01-31T17:35:04.586Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2} 2023-01-31T17:35:26.846Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2} 2023-01-31T17:36:08.356Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2} 2023-01-31T17:36:35.257Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2} 2023-01-31T17:46:16.623Z [DEBUG] (pool-2-thread-39) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=XXXX#2}

I'm still getting duplicate client id yes. There's no "#3" connection. Looks like the first #2 was at 17:33.

[MikeDombo]

We just released Nucleus 2.9.3 a minute ago, please retry using Nucleus 2.9.3.

[crispinboylan-int]

thanks, will check and get back.

[crispinboylan-int]

unfortunately i'm still seeing this with 2.9.3

[MikeDombo]

Please create a support case through the AWS Console and provide the full, uncut, debug logs from /greengrass/v2/logs. Please include all log files from that directory. If possible, please also include a dump of the AWSIoTV2 CloudWatch logs for the affected time. Please ensure in the logs that you provide, that you're using Nucleus version 2.9.3 which has fixed a potential cause for duplicate client IDs.

[crispinboylan-int]

ok will do that. just tried again and noticed these logs on the very first instance of it:

2023-02-08T17:50:40.845Z [DEBUG] (pool-2-thread-36) com.aws.greengrass.mqttclient.MqttClient: Getting new MQTT connection. {clientId=home-0U5Ia8Rfl8TS#2} 2023-02-08T17:50:40.851Z [INFO] (pool-2-thread-36) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-02-08T17:50:40.938Z [DEBUG] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Disconnecting from AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-02-08T17:50:40.938Z [DEBUG] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Successfully disconnected from AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2}

so it connects #2 then disconnects #2 above.

it then starts connecting using#2 but gets 'purposefully interrupted':

2023-02-08T17:50:51.957Z [INFO] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2} 2023-02-08T17:50:51.957Z [INFO] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection purposefully interrupted. {clientId=home-0U5Ia8Rfl8TS#2}

then does some stuff:

2023-02-08T17:50:51.957Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.CloudDataClient: Received cloud update sync request. {thing name=home-0U5Ia8Rfl8TS, shadow name=Climate} 2023-02-08T17:50:51.958Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest: Local shadow already contains update payload. No sync is necessary. {thing name=home-0U5Ia8Rfl8TS, shadow name=Climate} 2023-02-08T17:50:51.958Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: Ignoring sync request since update is not necessary. {thing name=home-0U5Ia8Rfl8TS, shadow name=Climate, type=class com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest} 2023-02-08T17:50:51.959Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.CloudDataClient: Received cloud update sync request. {thing name=home-0U5Ia8Rfl8TS, shadow name=AirQuality} 2023-02-08T17:50:51.960Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest: Local shadow already contains update payload. No sync is necessary. {thing name=home-0U5Ia8Rfl8TS, shadow name=AirQuality} 2023-02-08T17:50:51.960Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: Ignoring sync request since update is not necessary. {thing name=home-0U5Ia8Rfl8TS, shadow name=AirQuality, type=class com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest}

then it is successfully connected again to #2 and subscribes.

2023-02-08T17:50:52.057Z [INFO] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Successfully connected to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2, sessionPresent=false} 2023-02-08T17:50:52.057Z [DEBUG] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Subscribing to topic. {clientId=home-0U5Ia8Rfl8TS#2, qos=AT_LEAST_ONCE, topic=$aws/things/home-0U5Ia8Rfl8TS/jobs/ac186b04-c8c1-43ed-abae-b462ca9ebda3/namespace-aws-gg-deployment/update/rejected} 2023-02-08T17:50:52.085Z [DEBUG] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Successfully subscribed to topic. {clientId=home-0U5Ia8Rfl8TS#2, qos=AT_LEAST_ONCE, topic=$aws/things/home-0U5Ia8Rfl8TS/jobs/ac186b04-c8c1-43ed-abae-b462ca9ebda3/namespace-aws-gg-deployment/update/rejected}

it then connects again using #2 but notice the different thread id here where it connects:

2023-02-08T17:50:52.091Z [INFO] (pool-2-thread-45) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connecting to AWS IoT Core. {clientId=home-0U5Ia8Rfl8TS#2}

the original thread then gets disconnected:

2023-02-08T17:50:52.176Z [WARN] (Thread-4) com.aws.greengrass.mqttclient.AwsIotMqttClient: Connection interrupted. {clientId=home-0U5Ia8Rfl8TS#2, error=The connection was closed unexpectedly.}

[crispinboylan-int]

Restart Greengrass Deploy (revised deployment with no material changes) Deploy (revised deployment with no material changes) <-- error comes

[MikeDombo]

What is your full Java version? output of java -version.

Can you try using Amazon Corretto 8? https://docs.aws.amazon.com/corretto/latest/corretto-8-ug/downloads-list.html

Based on the logs you just provided, it seems like you're experiencing a race condition which cannot happen where one thread sees that we are connected, but the connection is null so it tries to then create a new connection. Like I said, this shouldn't be possible and I'm wondering if the JVM version has something to do with it.

[crispinboylan-int]

its openjdk 17 from ubuntu 22.04:

openjdk version "17.0.5" 2022-10-18 OpenJDK Runtime Environment (build 17.0.5+8-Ubuntu-2ubuntu122.04) OpenJDK 64-Bit Server VM (build 17.0.5+8-Ubuntu-2ubuntu122.04, mixed mode, sharing)

[MikeDombo]

I added another change to hopefully fix your issue in Nucleus 2.9.4. Please try this version if you're still having this issue.

[MikeDombo]

I will close this issue soon if we don't hear anything. Is this still a problem when using the very latest versions of Nucleus and Shadow Manager?