aws-greengrass / aws-greengrass-shadow-manager

A GreengrassV2 Component that provides offline device shadow documents and optional synchronization to the IoT device shadow service.
Apache License 2.0
9 stars 6 forks source link

(Shadow Manager): Shadow synchronization with MQTT bridge failing #189

Closed rodmaz closed 1 year ago

rodmaz commented 1 year ago

Describe the bug Whenever we update a shadow (classic or named), the shadow is apparently updated locally by com.aws.greengrass.shadowmanager. However its interaction with MQTT bridge and Pubsub is failing with strange error:

com.aws.greengrass.mqtt.bridge.clients.MQTTClient: MQTT publish failed. {topic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta}
Client is not connected (32104)

Expected behavior No error in MQTT bridge when publishing shadow changes. Greengrass clients devices should be able to retrieve shadow documents via local MQTT.

Actual behavior When we update a thing shadow in AWS IoT Core, we see the following logs in Greengrass Core device.

2023-08-17T18:26:30.208Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.CloudDataClient: Received cloud update sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T18:26:30.209Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Adding new sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=, type=class com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest}
2023-08-17T18:26:30.209Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=LocalUpdateSyncRequest, thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T18:26:30.210Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"state":{"desired":{"welcome":"hello","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692296790},"version":{"timestamp":1692296790}},"reported":{"welcome":{"timestamp":1692296790}}},"version":5,"timestamp":1692296790}, {"state":{"desired":{"welcome":"hello","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692296790},"version":{"timestamp":1692296790}},"reported":{"welcome":{"timestamp":1692296790}}},"version":5,"timestamp":1692296790}, $). {}
...
2023-08-17T18:26:30.235Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ipc.UpdateThingShadowRequestHandler: handle-update-thing-shadow. {thing name=swx-anchor-f412fa526bdc, shadow name=, updatedShadowStateSize=58}
2023-08-17T18:26:30.240Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/delta. {componentName=aws.greengrass.ShadowManager}
2023-08-17T18:26:30.241Z [DEBUG] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta, source=Pubsub}
2023-08-17T18:26:30.241Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/documents. {componentName=aws.greengrass.ShadowManager}
2023-08-17T18:26:30.241Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted. {componentName=aws.greengrass.ShadowManager}
2023-08-17T18:26:30.242Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ipc.UpdateThingShadowRequestHandler: Successfully updated shadow. {service-name=aws.greengrass.ShadowManager, thing name=swx-anchor-f412fa526bdc, shadow name=, local-version=3}
2023-08-17T18:26:30.242Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Adding new sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=, type=class com.aws.greengrass.shadowmanager.sync.model.CloudUpdateSyncRequest}
2023-08-17T18:26:30.242Z [ERROR] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: MQTT publish failed. {topic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta}
Client is not connected (32104)
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:31)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.sendNoWait(ClientComms.java:205)
        at org.eclipse.paho.client.mqttv3.MqttAsyncClient.publish(MqttAsyncClient.java:1375)
        at org.eclipse.paho.client.mqttv3.MqttClient.publish(MqttClient.java:570)
        at com.aws.greengrass.mqtt.bridge.clients.MQTTClient.publish(MQTTClient.java:190)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$0(MessageBridge.java:113)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$2(MessageBridge.java:132)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
        at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
        at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
        at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
        at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.handleMessage(MessageBridge.java:132)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$updateSubscriptionsForClient$6(MessageBridge.java:182)
        at com.aws.greengrass.mqtt.bridge.clients.PubSubClient.lambda$new$0(PubSubClient.java:42)
        at com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent.lambda$handlePublishToTopicRequest$2(PubSubIPCEventStreamAgent.java:190)
        at com.aws.greengrass.util.OrderedExecutorService$OrderedTask.run(OrderedExecutorService.java:91)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)

2023-08-17T18:26:30.242Z [ERROR] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.MessageBridge: Failed to publish. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta}
2023-08-17T18:26:30.242Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ShadowManagerDAOImpl: Updating sync info. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=5, local-version=3}
2023-08-17T18:26:30.244Z [DEBUG] (pool-2-thread-71) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents, source=Pubsub}
2023-08-17T18:26:30.245Z [ERROR] (pool-2-thread-71) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: MQTT publish failed. {topic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents}
Client is not connected (32104)
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:31)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.sendNoWait(ClientComms.java:205)
        at org.eclipse.paho.client.mqttv3.MqttAsyncClient.publish(MqttAsyncClient.java:1375)
        at org.eclipse.paho.client.mqttv3.MqttClient.publish(MqttClient.java:570)
        at com.aws.greengrass.mqtt.bridge.clients.MQTTClient.publish(MQTTClient.java:190)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$0(MessageBridge.java:113)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$2(MessageBridge.java:132)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
        at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
        at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
        at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
        at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.handleMessage(MessageBridge.java:132)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$updateSubscriptionsForClient$6(MessageBridge.java:182)
        at com.aws.greengrass.mqtt.bridge.clients.PubSubClient.lambda$new$0(PubSubClient.java:42)
        at com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent.lambda$handlePublishToTopicRequest$2(PubSubIPCEventStreamAgent.java:190)
        at com.aws.greengrass.util.OrderedExecutorService$OrderedTask.run(OrderedExecutorService.java:91)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)

2023-08-17T18:26:30.245Z [ERROR] (pool-2-thread-71) com.aws.greengrass.mqtt.bridge.MessageBridge: Failed to publish. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents}
2023-08-17T18:26:30.246Z [DEBUG] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted, source=Pubsub}
2023-08-17T18:26:30.246Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest: Successfully updated local shadow. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=5, local-version=3}
2023-08-17T18:26:30.246Z [ERROR] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: MQTT publish failed. {topic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted}
Client is not connected (32104)
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:31)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.sendNoWait(ClientComms.java:205)
        at org.eclipse.paho.client.mqttv3.MqttAsyncClient.publish(MqttAsyncClient.java:1375)
        at org.eclipse.paho.client.mqttv3.MqttClient.publish(MqttClient.java:570)
        at com.aws.greengrass.mqtt.bridge.clients.MQTTClient.publish(MQTTClient.java:190)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$0(MessageBridge.java:113)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$handleMessage$2(MessageBridge.java:132)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
        at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
        at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
        at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1764)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
        at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
        at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.handleMessage(MessageBridge.java:132)
        at com.aws.greengrass.mqtt.bridge.MessageBridge.lambda$updateSubscriptionsForClient$6(MessageBridge.java:182)
        at com.aws.greengrass.mqtt.bridge.clients.PubSubClient.lambda$new$0(PubSubClient.java:42)
        at com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent.lambda$handlePublishToTopicRequest$2(PubSubIPCEventStreamAgent.java:190)
        at com.aws.greengrass.util.OrderedExecutorService$OrderedTask.run(OrderedExecutorService.java:91)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)

2023-08-17T18:26:30.246Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=CloudUpdateSyncRequest, thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T18:26:30.247Z [ERROR] (pool-2-thread-70) com.aws.greengrass.mqtt.bridge.MessageBridge: Failed to publish. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted}
2023-08-17T18:26:30.254Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.model.CloudUpdateSyncRequest: Cloud shadow already contains update payload. No sync is necessary. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=5, local-version=3}

Environment

Additional context

MQTT bridge configuration allowing full communication between Pubsub and LocalMqtt:

{
    "mqttTopicMapping": {
        "ShadowLocalMQTTToPubsub": {
            "source": "LocalMqtt",
            "target": "Pubsub",
            "topic": "$aws/things/+/shadow/#"
        },
        "ShadowPubsubToLocalMQTT": {
            "source": "Pubsub",
            "target": "LocalMqtt",
            "topic": "$aws/things/+/shadow/#"
        }
    },
    "startupTimeoutSeconds": "120"
}

Issue is not allowing our Greengrass client devices to obtain shadow documents.

  1. Clients post to topic $aws/things/swx-anchor-f412fa526bdc/shadow/get
  2. Log in Greengrass Core:
2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.metrics.MQTTMessageLogger: C->B PUBLISH <swx-anchor-f412fa526bdc> to topics <$aws/things/swx-anchor-f412fa526bdc/shadow/get>. {}
2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.MQTTConnection: Received MQTT message, type: PUBLISH. {}
2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.PostOffice: Routing cmd [PUB QoS0] for session [swx-anchor-f412fa526bdc] to event processor 3. {}
2023-08-17T18:28:37.226Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.MQTTConnection: readCompleted client CId: swx-anchor-f412fa526bdc. {}
2023-08-17T18:28:37.226Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.DeviceAuthClient: Processing authorization request. {resource=mqtt:topic:$aws/things/swx-anchor-f412fa526bdc/shadow/get, action=mqtt:publish, sessionId=8f2b26f7-4875-418b-ae17-24bf98e4148c}
2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.PermissionEvaluationUtils: Hit policy with permission Permission(principal=swx-anchors, operation=mqtt:publish, resource=mqtt:topic:$aws/things/swx-anchor-f412fa526bdc/shadow/get). {}
2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully authorized client device action. {}
2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=AuthorizeClientDeviceActionEvent, eventHandler=AuthorizeClientDeviceActionsMetricHandler}
2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.mqtt.moquette.ClientDeviceAuthorizer: MQTT publish request. {isAllowed=true, clientId=swx-anchor-f412fa526bdc, topic=$aws/things/swx-anchor-f412fa526bdc/shadow/get}
2023-08-17T18:28:37.228Z [DEBUG] (pool-11-thread-1) io.moquette.interception.BrokerInterceptor: Notifying MQTT PUBLISH message to interceptor. CId=swx-anchor-f412fa526bdc, messageId=-1, topic=$aws/things/swx-anchor-f412fa526bdc/shadow/get, interceptorId=ClientDeviceConnectionTerminationListener. {}
  1. Greengrass clients receive nothing in either subscribed topics $aws/things/swx-anchor-f412fa526bdc/shadow/get/accepted or $aws/things/swx-anchor-f412fa526bdc/shadow/get/rejected.
MikeDombo commented 1 year ago

What you're talking about seems to be entirely unrelated to shadows. The mqtt bridge just isn't connected. Please provide the configuration you're using for the mqtt broker component and full logs showing the bridge connection attempt to the broker.

rodmaz commented 1 year ago

@MikeDombo Thanks for the prompt reply. MQTT Bridge is running though. This is the configuration from Greengrass-cli:

Component Name: aws.greengrass.clientdevices.mqtt.Bridge
    Version: 2.2.6
    State: RUNNING
    Configuration:

{
    "mqttTopicMapping": {
        "ShadowLocalMQTTToPubsub": {
            "source": "LocalMqtt",
            "target": "Pubsub",
            "topic": "$aws/things/+/shadow/#"
        },
        "ShadowPubsubToLocalMQTT": {
            "source": "Pubsub",
            "target": "LocalMqtt",
            "topic": "$aws/things/+/shadow/#"
        }
    },
    "startupTimeoutSeconds": "120"
}

When we restart the bridge component, we see these logs:

2023-08-17T19:03:14.052Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING}
2023-08-17T19:03:14.061Z [INFO] (Thread-7) software.amazon.awssdk.eventstreamrpc.RpcServer: Server connection closed code [socket is closed.]: [Id 67, Class ServerConnection, Refs 1](2023-08-17T19:03:13.810021Z) - <null>. {}
2023-08-17T19:03:29.054Z [ERROR] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-errored. {reason=Timeout in shutdown, serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, statusCode=SHUTDOWN_TIMEOUT}
2023-08-17T19:03:29.054Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, newState=ERRORED}
2023-08-17T19:03:29.055Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, newState=ERRORED}
2023-08-17T19:03:29.067Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.util.MqttChunkedPayloadPublisher: MQTT publish succeeded. {topic=$aws/things/swx-edge-gateway-7a9e860c508f0f0dfbd4c00bd5845d0c/greengrassv2/health/json}
2023-08-17T19:03:29.067Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=ERRORED_COMPONENT, serviceName=FleetStatusService, currentState=RUNNING}
2023-08-17T19:03:29.072Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=INSTALLED}
2023-08-17T19:03:29.072Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=INSTALLED}

2023-08-17T19:03:29.076Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.ai.senseworks.CollectRTLSPositions:NEW, services.ai.senseworks.CollectAnchorsStatus:NEW, services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=INSTALLED}
2023-08-17T19:03:29.076Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:03:29.076Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: Scheduling backingTask waiting for dependency ready. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:03:29.077Z [DEBUG] (pool-2-thread-73) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-awaiting-start. waiting for dependencies to start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:03:29.078Z [DEBUG] (pool-2-thread-73) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED, newState=STARTING}
2023-08-17T19:03:29.078Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED, newState=STARTING}
2023-08-17T19:03:29.078Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.ai.senseworks.CollectRTLSPositions:NEW, services.ai.senseworks.CollectAnchorsStatus:NEW, services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=INSTALLED}

2023-08-17T19:03:29.080Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.ai.senseworks.CollectRTLSPositions:NEW, services.ai.senseworks.CollectAnchorsStatus:NEW, services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=INSTALLED}
2023-08-17T19:03:29.080Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING}
2023-08-17T19:03:29.081Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: Scheduling backingTask start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING}
2023-08-17T19:03:31.069Z [INFO] (pool-2-thread-73) com.aws.greengrass.clientdevices.auth.certificate.ClientCertificateGenerator: New client certificate generated. {reason=initialization of client cert subscription, subject=C=US,O=Amazon.com Inc.,OU=Amazon Web Services,ST=Washington,L=Seattle,CN=aws.greengrass.clientdevices.mqtt.Bridge, certExpiry=2023-08-24T19:03:31Z}
2023-08-17T19:03:31.069Z [DEBUG] (pool-2-thread-73) com.aws.greengrass.mqtt.bridge.auth.MQTTClientKeyStore: Storing new client certificate to be used on next connect attempt. {}
2023-08-17T19:03:31.086Z [INFO] (nioEventLoopGroup-3-8) io.moquette.broker.metrics.MQTTMessageLogger: C->B DISCONNECT <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:03:31.086Z [DEBUG] (nioEventLoopGroup-3-8) io.moquette.broker.MQTTConnection: Received MQTT message, type: DISCONNECT. {}
2023-08-17T19:03:31.086Z [DEBUG] (nioEventLoopGroup-3-8) io.moquette.broker.PostOffice: Routing cmd [DISCONN] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:03:31.087Z [DEBUG] (nioEventLoopGroup-3-8) io.moquette.broker.MQTTConnection: readCompleted client CId: mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:03:31.087Z [DEBUG] (Session Executor 2) io.moquette.interception.BrokerInterceptor: Notifying MQTT client disconnection to interceptor. CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:03:31.088Z [INFO] (pool-2-thread-73) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Connecting to broker. {clientId=mqtt-bridge-46ne0rf0wmp, brokerUri=ssl://localhost:8883}
2023-08-17T19:03:31.088Z [INFO] (nioEventLoopGroup-3-8) io.moquette.broker.metrics.MQTTMessageLogger: Channel Inactive. {}
2023-08-17T19:03:31.089Z [DEBUG] (nioEventLoopGroup-3-8) io.moquette.broker.MQTTConnection: Notifying connection lost event. {}
2023-08-17T19:03:31.089Z [DEBUG] (nioEventLoopGroup-3-8) io.moquette.broker.PostOffice: Routing cmd [CONN LOST] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:03:31.089Z [DEBUG] (Session Executor 2) io.moquette.broker.MQTTConnection: Cleaning mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:03:31.089Z [DEBUG] (Session Executor 2) io.moquette.broker.MQTTConnection: Remove session for client mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:03:31.089Z [DEBUG] (Session Executor 2) io.moquette.interception.BrokerInterceptor: Notifying unexpected MQTT client disconnection to interceptor CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:03:31.106Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.AutoFlushHandler: Initializing autoflush handler on channel [id: 0x213e707f, L:/127.0.0.1:8883 - R:/127.0.0.1:41830] Cid: null. {}
2023-08-17T19:03:31.139Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.148Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully verified client device identity. {}
2023-08-17T19:03:31.148Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=VerifyClientDeviceIdentityEvent, eventHandler=VerifyClientDeviceIdentityEventHandler}
2023-08-17T19:03:31.148Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.150Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.189Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.191Z [DEBUG] (nioEventLoopGroup-3-7) io.netty.handler.ssl.SslHandler: [id: 0x213e707f, L:/127.0.0.1:8883 - R:/127.0.0.1:41830] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384. {}
2023-08-17T19:03:31.191Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.496Z [INFO] (nioEventLoopGroup-3-7) io.moquette.broker.metrics.MQTTMessageLogger: C->B CONNECT <null>. {}
2023-08-17T19:03:31.497Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: Received MQTT message, type: CONNECT. {}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.session.SessionManager: Creating new session. {SessionId=1ac397e6-33f3-4e9e-afd4-796819064cf7}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.session.SessionManager: Successfully created a session with device credentials. {}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=SessionCreationEvent, eventHandler=SessionCreationEventHandler}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.DeviceAuthClient: Processing authorization request. {resource=mqtt:clientId:mqtt-bridge-46ne0rf0wmp, action=mqtt:connect, sessionId=1ac397e6-33f3-4e9e-afd4-796819064cf7}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully authorized client device action. {}
2023-08-17T19:03:31.499Z [DEBUG] (nioEventLoopGroup-3-7) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=AuthorizeClientDeviceActionEvent, eventHandler=AuthorizeClientDeviceActionsMetricHandler}
2023-08-17T19:03:31.499Z [INFO] (nioEventLoopGroup-3-7) com.aws.greengrass.mqtt.moquette.ClientDeviceAuthorizer: Successfully authenticated client device. {clientId=mqtt-bridge-46ne0rf0wmp, sessionId=1ac397e6-33f3-4e9e-afd4-796819064cf7}
2023-08-17T19:03:31.500Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.PostOffice: Routing cmd [CONN] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:03:31.500Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:03:31.500Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.metrics.MQTTMessageLogger: C<-B CONNACK <null>. {}
2023-08-17T19:03:31.502Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: Connection has been configured CId=mqtt-bridge-46ne0rf0wmp, keepAlive=60, removeTemporaryQoS2=true, idleTime=90. {}
2023-08-17T19:03:31.504Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.InflightResender: Initializing autoflush handler on channel [id: 0x213e707f, L:/127.0.0.1:8883 - R:/127.0.0.1:41830]. {}
2023-08-17T19:03:31.504Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.interception.BrokerInterceptor: Sending MQTT CONNECT message to interceptor. CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:03:31.505Z [INFO] (pool-2-thread-74) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Connected to broker. {clientId=mqtt-bridge-46ne0rf0wmp, brokerUri=ssl://localhost:8883}
2023-08-17T19:03:31.505Z [DEBUG] (pool-2-thread-74) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Subscribing to MQTT topics. {topics=[]}
2023-08-17T19:04:31.508Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.metrics.MQTTMessageLogger: C->B PINGREQ <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:04:31.509Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: Received MQTT message, type: PINGREQ. {}
2023-08-17T19:04:31.509Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.metrics.MQTTMessageLogger: C<-B PINGRESP <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:04:31.509Z [DEBUG] (nioEventLoopGroup-3-7) io.moquette.broker.MQTTConnection: readCompleted client CId: mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:05:29.081Z [ERROR] (pool-1-thread-3) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-errored. {reason=startup timeout, serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, statusCode=STARTUP_TIMEOUT}
2023-08-17T19:05:29.081Z [DEBUG] (pool-1-thread-3) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, newState=ERRORED}
2023-08-17T19:05:29.083Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, newState=ERRORED}
2023-08-17T19:05:29.086Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.util.MqttChunkedPayloadPublisher: MQTT publish succeeded. {topic=$aws/things/swx-edge-gateway-7a9e860c508f0f0dfbd4c00bd5845d0c/greengrassv2/health/json}
2023-08-17T19:05:29.086Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=ERRORED_COMPONENT, serviceName=FleetStatusService, currentState=RUNNING}

And now bridge component is BROKEN.

Should I move this issue to the Github bridge component repo?

MikeDombo commented 1 year ago

Bridge running does not mean that it is connected, as the error log previously showed.

If you publish now, does it work? The log you just posted shows the bridge client is now connected.

rodmaz commented 1 year ago

Removed all our custom components, redeployed and MQTT bridge seems fine. However when we changed the classic shadow in IoT core, we see following log messages on GG Core:

2023-08-17T19:18:30.036Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.CloudDataClient: Received cloud update sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T19:18:30.036Z [DEBUG] (Thread-4) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Adding new sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=, type=class com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest}
2023-08-17T19:18:30.037Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=LocalUpdateSyncRequest, thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T19:18:30.038Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $). {}
2023-08-17T19:18:30.038Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $). {}
2023-08-17T19:18:30.038Z [DEBUG] (pool-2-thread-26) com.networknt.schema.PropertiesValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $). {}
2023-08-17T19:18:30.038Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $). {}
2023-08-17T19:18:30.038Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.PropertiesValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.desired). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.UnionTypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.desired). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.desired). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.reported). {}
2023-08-17T19:18:30.039Z [DEBUG] (pool-2-thread-26) com.networknt.schema.UnionTypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.reported). {}
2023-08-17T19:18:30.040Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state.reported). {}
2023-08-17T19:18:30.040Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state). {}
2023-08-17T19:18:30.040Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.state). {}
2023-08-17T19:18:30.040Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( 6, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.version). {}
2023-08-17T19:18:30.040Z [DEBUG] (pool-2-thread-26) com.networknt.schema.MinimumValidator: validate( 6, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}},"version":6,"timestamp":1692299909}, $.version). {}
2023-08-17T19:18:30.064Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $). {}
2023-08-17T19:18:30.064Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $). {}
2023-08-17T19:18:30.064Z [DEBUG] (pool-2-thread-26) com.networknt.schema.PropertiesValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.PropertiesValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.desired). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.UnionTypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.desired). {}
2023-08-17T19:18:30.065Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"changed","version":"2.0.0"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.desired). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.reported). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.UnionTypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.reported). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.TypeValidator: validate( {"welcome":"aws-iot"}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state.reported). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $.state). {}
2023-08-17T19:18:30.066Z [DEBUG] (pool-2-thread-26) com.networknt.schema.RequiredValidator: validate( {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, {"state":{"desired":{"welcome":"changed","version":"2.0.0"},"reported":{"welcome":"aws-iot"}},"metadata":{"desired":{"welcome":{"timestamp":1692299909},"version":{"timestamp":1692299909}},"reported":{"welcome":{"timestamp":1692299909}}}}, $). {}
2023-08-17T19:18:30.067Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ipc.UpdateThingShadowRequestHandler: handle-update-thing-shadow. {thing name=swx-anchor-f412fa526bdc, shadow name=, updatedShadowStateSize=60}
2023-08-17T19:18:30.073Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/delta. {componentName=aws.greengrass.ShadowManager}
2023-08-17T19:18:30.074Z [DEBUG] (pool-2-thread-94) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta, source=Pubsub}
2023-08-17T19:18:30.074Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/documents. {componentName=aws.greengrass.ShadowManager}
2023-08-17T19:18:30.075Z [ERROR] (pool-2-thread-94) com.aws.greengrass.mqtt.bridge.MessageBridge: Message client not found for target type. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/delta}
2023-08-17T19:18:30.075Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.builtin.services.pubsub.PubSubIPCEventStreamAgent: Sending publish event for topic $aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted. {componentName=aws.greengrass.ShadowManager}
2023-08-17T19:18:30.075Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ipc.UpdateThingShadowRequestHandler: Successfully updated shadow. {service-name=aws.greengrass.ShadowManager, thing name=swx-anchor-f412fa526bdc, shadow name=, local-version=4}
2023-08-17T19:18:30.075Z [DEBUG] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents, source=Pubsub}
2023-08-17T19:18:30.075Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Adding new sync request. {thing name=swx-anchor-f412fa526bdc, shadow name=, type=class com.aws.greengrass.shadowmanager.sync.model.CloudUpdateSyncRequest}
2023-08-17T19:18:30.076Z [ERROR] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.MessageBridge: Message client not found for target type. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/documents}
2023-08-17T19:18:30.076Z [DEBUG] (pool-2-thread-94) com.aws.greengrass.mqtt.bridge.MessageBridge: Message received. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted, source=Pubsub}
2023-08-17T19:18:30.076Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.ShadowManagerDAOImpl: Updating sync info. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=6, local-version=4}
2023-08-17T19:18:30.076Z [ERROR] (pool-2-thread-94) com.aws.greengrass.mqtt.bridge.MessageBridge: Message client not found for target type. {sourceTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted, source=Pubsub, targetTopic=, target=LocalMqtt, resolvedTargetTopic=$aws/things/swx-anchor-f412fa526bdc/shadow/update/accepted}
2023-08-17T19:18:30.080Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.model.LocalUpdateSyncRequest: Successfully updated local shadow. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=6, local-version=4}
2023-08-17T19:18:30.080Z [INFO] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.strategy.BaseSyncStrategy: sync. Executing sync request. {Type=CloudUpdateSyncRequest, thing name=swx-anchor-f412fa526bdc, shadow name=}
2023-08-17T19:18:30.089Z [DEBUG] (pool-2-thread-26) com.aws.greengrass.shadowmanager.sync.model.CloudUpdateSyncRequest: Cloud shadow already contains update payload. No sync is necessary. {thing name=swx-anchor-f412fa526bdc, shadow name=, cloud-version=6, local-version=4}
2023-08-17T19:18:31.593Z [ERROR] (pool-1-thread-3) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-errored. {reason=startup timeout, serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, statusCode=STARTUP_TIMEOUT}
2023-08-17T19:18:31.594Z [DEBUG] (pool-1-thread-3) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, newState=ERRORED}
2023-08-17T19:18:31.594Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING, newState=ERRORED}
2023-08-17T19:18:31.596Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.util.MqttChunkedPayloadPublisher: MQTT publish succeeded. {topic=$aws/things/swx-edge-gateway-7a9e860c508f0f0dfbd4c00bd5845d0c/greengrassv2/health/json}
2023-08-17T19:18:31.596Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=ERRORED_COMPONENT, serviceName=FleetStatusService, currentState=RUNNING}
2023-08-17T19:18:31.596Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.596Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.597Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.597Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.597Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.597Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.598Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED}
2023-08-17T19:18:31.599Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=STOPPING}
2023-08-17T19:18:31.599Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=STOPPING}
2023-08-17T19:18:31.600Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING}
2023-08-17T19:18:34.089Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.metrics.MQTTMessageLogger: C->B PINGREQ <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:18:34.089Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.MQTTConnection: Received MQTT message, type: PINGREQ. {}
2023-08-17T19:18:34.089Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.metrics.MQTTMessageLogger: C<-B PINGRESP <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:18:34.090Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.MQTTConnection: readCompleted client CId: mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:18:46.601Z [ERROR] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-errored. {reason=Timeout in shutdown, serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, statusCode=SHUTDOWN_TIMEOUT}
2023-08-17T19:18:46.601Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, newState=ERRORED}
2023-08-17T19:18:46.601Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: Stopping backingTask start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING}
2023-08-17T19:18:46.602Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STOPPING, newState=ERRORED}
2023-08-17T19:18:46.603Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.util.MqttChunkedPayloadPublisher: MQTT publish succeeded. {topic=$aws/things/swx-edge-gateway-7a9e860c508f0f0dfbd4c00bd5845d0c/greengrassv2/health/json}
2023-08-17T19:18:46.603Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.status.FleetStatusService: fss-status-update-published. Status update published to FSS. {trigger=ERRORED_COMPONENT, serviceName=FleetStatusService, currentState=RUNNING}
2023-08-17T19:18:46.603Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.603Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.604Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.605Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:ERRORED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.606Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED}
2023-08-17T19:18:46.606Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=INSTALLED}
2023-08-17T19:18:46.606Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=ERRORED, newState=INSTALLED}
2023-08-17T19:18:46.606Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.606Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.606Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.607Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:INSTALLED], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.608Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:18:46.609Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: Scheduling backingTask waiting for dependency ready. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:18:46.609Z [DEBUG] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-awaiting-start. waiting for dependencies to start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED}
2023-08-17T19:18:46.609Z [DEBUG] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-report-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED, newState=STARTING}
2023-08-17T19:18:46.609Z [INFO] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-set-state. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=INSTALLED, newState=STARTING}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.610Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.611Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.612Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.612Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.lifecyclemanager.GenericExternalService: continue-waiting-for-dependencies. {waitingFor=[services.aws.greengrass.clientdevices.mqtt.Bridge:STARTING], serviceName=main, currentState=FINISHED}
2023-08-17T19:18:46.612Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: service-state-transition-start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING}
2023-08-17T19:18:46.612Z [DEBUG] (aws.greengrass.clientdevices.mqtt.Bridge-lifecycle) com.aws.greengrass.mqtt.bridge.MQTTBridge: Scheduling backingTask start. {serviceName=aws.greengrass.clientdevices.mqtt.Bridge, currentState=STARTING}
2023-08-17T19:18:52.341Z [INFO] (pool-2-thread-95) com.aws.greengrass.clientdevices.auth.certificate.ClientCertificateGenerator: New client certificate generated. {reason=initialization of client cert subscription, subject=C=US,O=Amazon.com Inc.,OU=Amazon Web Services,ST=Washington,L=Seattle,CN=aws.greengrass.clientdevices.mqtt.Bridge, certExpiry=2023-08-24T19:18:52Z}
2023-08-17T19:18:52.341Z [DEBUG] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.auth.MQTTClientKeyStore: Storing new client certificate to be used on next connect attempt. {}
2023-08-17T19:18:52.357Z [INFO] (nioEventLoopGroup-3-3) io.moquette.broker.metrics.MQTTMessageLogger: C->B DISCONNECT <mqtt-bridge-46ne0rf0wmp>. {}
2023-08-17T19:18:52.357Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.MQTTConnection: Received MQTT message, type: DISCONNECT. {}
2023-08-17T19:18:52.357Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.PostOffice: Routing cmd [DISCONN] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:18:52.358Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.MQTTConnection: readCompleted client CId: mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:18:52.358Z [DEBUG] (Session Executor 2) io.moquette.interception.BrokerInterceptor: Notifying MQTT client disconnection to interceptor. CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:18:52.358Z [DEBUG] (pool-11-thread-1) com.aws.greengrass.mqtt.moquette.ClientDeviceAuthorizer: Closing auth session. {sessionId=0ef3b22a-8463-4833-89cb-2acf2fc67e11}
2023-08-17T19:18:52.358Z [DEBUG] (pool-11-thread-1) com.aws.greengrass.clientdevices.auth.session.SessionManager: Closing session. {SessionId=0ef3b22a-8463-4833-89cb-2acf2fc67e11}
2023-08-17T19:18:52.360Z [INFO] (nioEventLoopGroup-3-3) io.moquette.broker.metrics.MQTTMessageLogger: Channel Inactive. {}
2023-08-17T19:18:52.360Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.MQTTConnection: Notifying connection lost event. {}
2023-08-17T19:18:52.360Z [DEBUG] (nioEventLoopGroup-3-3) io.moquette.broker.PostOffice: Routing cmd [CONN LOST] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:18:52.361Z [DEBUG] (Session Executor 2) io.moquette.broker.MQTTConnection: Cleaning mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:18:52.361Z [DEBUG] (Session Executor 2) io.moquette.broker.MQTTConnection: Remove session for client mqtt-bridge-46ne0rf0wmp. {}
2023-08-17T19:18:52.361Z [DEBUG] (Session Executor 2) io.moquette.interception.BrokerInterceptor: Notifying unexpected MQTT client disconnection to interceptor CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:18:52.363Z [INFO] (pool-2-thread-95) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Connecting to broker. {clientId=mqtt-bridge-46ne0rf0wmp, brokerUri=ssl://localhost:8883}
2023-08-17T19:18:52.384Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.AutoFlushHandler: Initializing autoflush handler on channel [id: 0x2d88545f, L:/127.0.0.1:8883 - R:/127.0.0.1:55950] Cid: null. {}
2023-08-17T19:18:52.444Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:18:52.455Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully verified client device identity. {}
2023-08-17T19:18:52.455Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=VerifyClientDeviceIdentityEvent, eventHandler=VerifyClientDeviceIdentityEventHandler}
2023-08-17T19:18:52.457Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:18:52.490Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:18:52.491Z [DEBUG] (nioEventLoopGroup-3-4) io.netty.handler.ssl.SslHandler: [id: 0x2d88545f, L:/127.0.0.1:8883 - R:/127.0.0.1:55950] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384. {}
2023-08-17T19:18:52.491Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:18:52.795Z [INFO] (nioEventLoopGroup-3-4) io.moquette.broker.metrics.MQTTMessageLogger: C->B CONNECT <null>. {}
2023-08-17T19:18:52.796Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: Received MQTT message, type: CONNECT. {}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.session.SessionManager: Creating new session. {SessionId=f9a15e20-3cd0-4509-8d6e-8eb01f892c00}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.session.SessionManager: Successfully created a session with device credentials. {}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=SessionCreationEvent, eventHandler=SessionCreationEventHandler}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.DeviceAuthClient: Processing authorization request. {resource=mqtt:clientId:mqtt-bridge-46ne0rf0wmp, action=mqtt:connect, sessionId=f9a15e20-3cd0-4509-8d6e-8eb01f892c00}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully authorized client device action. {}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=AuthorizeClientDeviceActionEvent, eventHandler=AuthorizeClientDeviceActionsMetricHandler}
2023-08-17T19:18:52.797Z [INFO] (nioEventLoopGroup-3-4) com.aws.greengrass.mqtt.moquette.ClientDeviceAuthorizer: Successfully authenticated client device. {clientId=mqtt-bridge-46ne0rf0wmp, sessionId=f9a15e20-3cd0-4509-8d6e-8eb01f892c00}
2023-08-17T19:18:52.797Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.PostOffice: Routing cmd [CONN] for session [mqtt-bridge-46ne0rf0wmp] to event processor 2. {}
2023-08-17T19:18:52.798Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: readCompleted client CId: null. {}
2023-08-17T19:18:52.799Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.metrics.MQTTMessageLogger: C<-B CONNACK <null>. {}
2023-08-17T19:18:52.801Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.MQTTConnection: Connection has been configured CId=mqtt-bridge-46ne0rf0wmp, keepAlive=60, removeTemporaryQoS2=true, idleTime=90. {}
2023-08-17T19:18:52.801Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.broker.InflightResender: Initializing autoflush handler on channel [id: 0x2d88545f, L:/127.0.0.1:8883 - R:/127.0.0.1:55950]. {}
2023-08-17T19:18:52.801Z [DEBUG] (nioEventLoopGroup-3-4) io.moquette.interception.BrokerInterceptor: Sending MQTT CONNECT message to interceptor. CId=mqtt-bridge-46ne0rf0wmp, interceptorId=ClientDeviceConnectionTerminationListener. {}
2023-08-17T19:18:52.806Z [INFO] (pool-2-thread-96) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Connected to broker. {clientId=mqtt-bridge-46ne0rf0wmp, brokerUri=ssl://localhost:8883}
2023-08-17T19:18:52.806Z [DEBUG] (pool-2-thread-96) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Subscribing to MQTT topics. {topics=[]}
2023-08-17T19:19:00.883Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of logs.us-east-1.amazonaws.com/3.236.94.153:443. {}
2023-08-17T19:19:00.884Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of logs.us-east-1.amazonaws.com/3.236.94.153:443. {}
2023-08-17T19:19:00.885Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing logs.us-east-1.amazonaws.com/3.236.94.153:443. {}
2023-08-17T19:19:00.888Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down output of c2e2cq6gibxa8.credentials.iot.us-east-1.amazonaws.com/52.22.206.233:443. {}
2023-08-17T19:19:00.890Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: shutting down input of c2e2cq6gibxa8.credentials.iot.us-east-1.amazonaws.com/52.22.206.233:443. {}
2023-08-17T19:19:00.891Z [DEBUG] (idle-connection-reaper) software.amazon.awssdk.http.apache.internal.net.SdkSslSocket: closing c2e2cq6gibxa8.credentials.iot.us-east-1.amazonaws.com/52.22.206.233:443. {}

The error message is gone. But again, clients obtain no shadow document:

  1. Clients post to topic $aws/things/swx-anchor-f412fa526bdc/shadow/get`

  2. Log in Greengrass Core:

    2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.metrics.MQTTMessageLogger: C->B PUBLISH <swx-anchor-f412fa526bdc> to topics <$aws/things/swx-anchor-f412fa526bdc/shadow/get>. {}
    2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.MQTTConnection: Received MQTT message, type: PUBLISH. {}
    2023-08-17T18:28:37.225Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.PostOffice: Routing cmd [PUB QoS0] for session [swx-anchor-f412fa526bdc] to event processor 3. {}
    2023-08-17T18:28:37.226Z [DEBUG] (nioEventLoopGroup-3-6) io.moquette.broker.MQTTConnection: readCompleted client CId: swx-anchor-f412fa526bdc. {}
    2023-08-17T18:28:37.226Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.DeviceAuthClient: Processing authorization request. {resource=mqtt:topic:$aws/things/swx-anchor-f412fa526bdc/shadow/get, action=mqtt:publish, sessionId=8f2b26f7-4875-418b-ae17-24bf98e4148c}
    2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.PermissionEvaluationUtils: Hit policy with permission Permission(principal=swx-anchors, operation=mqtt:publish, resource=mqtt:topic:$aws/things/swx-anchor-f412fa526bdc/shadow/get). {}
    2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.api.ClientDevicesAuthServiceApi: Successfully authorized client device action. {}
    2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.clientdevices.auth.api.DomainEvents: Invoking event handler. {event=AuthorizeClientDeviceActionEvent, eventHandler=AuthorizeClientDeviceActionsMetricHandler}
    2023-08-17T18:28:37.227Z [DEBUG] (Session Executor 3) com.aws.greengrass.mqtt.moquette.ClientDeviceAuthorizer: MQTT publish request. {isAllowed=true, clientId=swx-anchor-f412fa526bdc, topic=$aws/things/swx-anchor-f412fa526bdc/shadow/get}
    2023-08-17T18:28:37.228Z [DEBUG] (pool-11-thread-1) io.moquette.interception.BrokerInterceptor: Notifying MQTT PUBLISH message to interceptor. CId=swx-anchor-f412fa526bdc, messageId=-1, topic=$aws/things/swx-anchor-f412fa526bdc/shadow/get, interceptorId=ClientDeviceConnectionTerminationListener. {}
  3. Greengrass clients receive nothing in either subscribed topics $aws/things/swx-anchor-f412fa526bdc/shadow/get/accepted or $aws/things/swx-anchor-f412fa526bdc/shadow/get/rejected.

rodmaz commented 1 year ago

What are the shadow topics Greengrass IoT devices should use when they want to retrieve its current shadow documents? This is not documented in Greengrass V2 but up to now we have assumed they are the same as IoT thing <---> IoT Core.

MikeDombo commented 1 year ago

Please review the documentation here for shadow syncing. https://docs.aws.amazon.com/greengrass/v2/developerguide/sync-shadows-with-iot-core.html and https://docs.aws.amazon.com/greengrass/v2/developerguide/work-with-client-device-shadows.html

MikeDombo commented 1 year ago

When you deployed again, did you configure bridge? The bridge isn't subscribing to anything.

2023-08-17T19:18:52.806Z [DEBUG] (pool-2-thread-96) com.aws.greengrass.mqtt.bridge.clients.MQTTClient: Subscribing to MQTT topics. {topics=[]}

rodmaz commented 1 year ago

Since we haven't managed yesterday to get the Greengrass Core health report back to "healthy", we decided to do a full reset and redeployed everything. Shadows are now correctly sync'ed as expected.

However our Greengrass core is however again reporting its device status as "Unhealthy" and we don't know why. Everything is working fine and there is no components in BROKEN state. Using greengrass-cli we can see all components are in state RUNNING, FINISHED or NEW. Probably off-topic here but it would be important to know how we can identify the reason.

MikeDombo commented 1 year ago

Look in the AWS console for broken component, but the local cli is always the source of truth. The console is updated only once per day and after deployments so it is expected to be outdated and eventually consistent.

MikeDombo commented 1 year ago

Closing since there hasn't been anything else posted here. Reopen or create new issues as may be required. Thanks