search

awslabs / aws-crt-python

Python bindings for the AWS Common Runtime
Apache License 2.0
87 stars 43 forks source link

Random crash using awscrt 0.14.0 inside a Python 3.10 docker container #383

Closed jfduque closed 2 years ago

jfduque commented 2 years ago

Hello,

I am using awscrt 0.14.0 & awsiotsdk 1.11.5 inside a docker container (Docker version: 20.10.17) as part of an AWS GreenGrass component. The container's base image is python:3.10-slim

After opening a connection to the GreenGrass core's IPC to receive messages from AWS IoT Core, the entire container crashes with the following trace:

[WARN] (Copier) moduleName: stderr. Signal received: -1972330112, errno: 32619. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. ################################################################################. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. Stack trace:. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. ################################################################################. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(aws_backtrace_print+0x4f) [0x7f6b9ecd791f]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0x726c3) [0x7f6b9ec456c3]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /lib/x86_64-linux-gnu/libc.so.6(+0x3bd60) [0x7f6b9f51ad60]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/libpython3.10.so.1.0(PyObject_GetAttrString+0xb) [0x7f6b9f7fcafb]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/libpython3.10.so.1.0(_PyObject_CallMethod_SizeT+0x7e) [0x7f6b9f8f1d6e]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0x6e9c7) [0x7f6b9ec419c7]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xd4980) [0x7f6b9eca7980]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xd5422) [0x7f6b9eca8422]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xd58a8) [0x7f6b9eca88a8]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xee3a6) [0x7f6b9ecc13a6]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xe6af6) [0x7f6b9ecb9af6]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0x106d22) [0x7f6b9ecd9d22]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0xe27c4) [0x7f6b9ecb57c4]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /usr/local/lib/python3.10/site-packages/_awscrt.cpython-310-x86_64-linux-gnu.so(+0x105217) [0x7f6b9ecd8217]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /lib/x86_64-linux-gnu/libpthread.so.0(+0x8ea7) [0x7f6b9f4c5ea7]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[WARN] (Copier) moduleName: stderr. /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f6b9f5dcdef]. {scriptName=services.moduleName.lifecycle.Run.Script, serviceName=moduleName, currentState=RUNNING}
[INFO] (Copier) moduleName: Run script exited. {exitCode=255, serviceName=moduleName, currentState=RUNNING}

I have tried deploying to the following Linux distributions:

But with any distribution the problem persists: random crashes and the containers do not even reach 24 hours of operation. Only on Rocky Linux do I get the following trace from time to time, I don't know if it is related:

Traceback (most recent call last):
  File "/usr/src/app/src/event_handler.py", line 134, in update_thing_shadow
    result = operation.get_response().result(self.timeout)
  File "/usr/local/lib/python3.10/concurrent/futures/_base.py", line 458, in result
    return self.__get_result()
  File "/usr/local/lib/python3.10/concurrent/futures/_base.py", line 403, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.10/site-packages/awsiot/eventstreamrpc.py", line 723, in _on_continuation_message
    raise shape
awsiot.greengrasscoreipc.model.ConflictError

Thanks in advance.

jfduque commented 2 years ago

Got the following message after further testing:

Fatal error condition occurred in /aws-crt-python/crt/aws-c-event-stream/source/event_stream_rpc_client.c:959: ref_count != 0 && "Continuation ref count has gone negative"
Exiting Application
xiazhvera commented 2 years ago

Hi @jfduque, thank you for reporting the issue. We are currently looking into it. Would you mind provide more logs by turn on the log as following example: 

from awscrt import io
...
...
io.init_logging(io.LogLevel.Debug, <output_file>);

It would also be nice to have more information about how was the connection get setup.
Thank you!

jfduque commented 2 years ago

Hi @jfduque, thank you for reporting the issue. We are currently looking into it. Would you mind provide more logs by turn on the log as following example:

from awscrt import io
...
...
io.init_logging(io.LogLevel.Debug, <output_file>);

It would also be nice to have more information about how was the connection get setup. Thank you!

Hi, thanks for answering.

This is how i've setup the connection:

import logging
import awsiot.greengrasscoreipc

logging.basicConfig(level=logging.INFO)

TIMEOUT = 10

ipc_client_local = awsiot.greengrasscoreipc.connect()
handler_local = LocalEventHandler() # some handler
operation_local = ipc_client_local.new_subscribe_to_iot_core(handler_local)
try:
    request_local = SubscribeToIoTCoreRequest()
    request_local.topic_name = "some_topic"
    request_local.qos = QOS.AT_LEAST_ONCE
    future_local = operation_local.activate(request_local)
    future_local.result(TIMEOUT)
except Exception as exc:
    logging.error(f"Exception while subscribing to topic", exc_info=True)
    operation_local.close()
    exit(1)
jfduque commented 2 years ago

Hi @jfduque, thank you for reporting the issue. We are currently looking into it. Would you mind provide more logs by turn on the log as following example:

from awscrt import io
...
...
io.init_logging(io.LogLevel.Debug, <output_file>);

I've managed to capture the following log 4-5 minutes before crashing:

[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: handler 0x7fcdac01a560 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [socket] - id=0x7fcdb405fd00 fd=18: closing
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac032c80: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00ea60: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac032c80: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00ea60: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: handler 0x7fcdac00e9c0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e6e8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e6e8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4066e80: channel 0x7fcdac00e6c0 shutdown with error 0.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb401ff50: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7fcdac00e6c0
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4066e80: releasing bootstrap reference
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb401ff50: destroying connection.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4066e80: releasing bootstrap reference
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: destroying channel.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac01a560: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4066e80: releasing bootstrap reference
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4066e80: destroying
[INFO] [2022-09-16T18:11:11Z] [00007fcdb1efb700] [event-loop] - id=0x7fcdb4033040: Destroying event_loop
[INFO] [2022-09-16T18:11:11Z] [00007fcdb1efb700] [event-loop] - id=0x7fcdb4033040: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdb40308c8: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdb40308c8: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [event-loop] - id=0x7fcdb4033040: exiting main loop
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac04b380: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:11:11Z] [00007fcdb1efb700] [task-scheduler] - id=0x7fcdac04b380: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: calculated prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: read total message length of 304
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: read prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - stream id header value 1
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb4017d00: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb4017d00: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb4017d00: Starting event-loop thread.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [dns] - id=0x7fcdb40349a0: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [channel-bootstrap] - id=0x7fcdb403b890: Initializing client bootstrap with event-loop group 0x7fcdb403e720
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb4023120 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb4023120 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb4023120 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb4023120 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb4023120 fd=18: connected immediately, not scheduling timeout.
[INFO] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-loop] - id=0x7fcdb4017d00: main loop started
[INFO] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-loop] - id=0x7fcdb4017d00: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdb4036120: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdb4036120: Running (null) task with <Running> status
[INFO] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [socket] - id=0x7fcdb4023120 fd=18: connection success
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [socket] - id=0x7fcdb4023120 fd=18: assigning to event loop 0x7fcdb4017d00
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: client connection on socket 0x7fcdb4023120 completed with error 0.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c03c300: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c03c300: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: no message pool is currently stored in the event-loop local storage, adding 0x7fcd9c000da0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: channel 0x7fcd9c000e60 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [socket-handler] - id=0x7fcd9c011cb0: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: on_channel_setup_fn invoked with error_code 0 with channel 0x7fcd9c000e60
[INFO] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - static: new handler is 0x7fcd9c01fb60
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: successful event-stream channel setup 0x7fcd9c000e60
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdac0009d0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdac0009d0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: read total message length of 71
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb4033630: continuation created 0x7fcdb402ff70
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb402ff70: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb4033630: operation name specified aws.greengrass#GetThingShadow
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdac0009d0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdac0009d0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: calculated prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: read total message length of 841
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: read prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: the terminate stream flag was specified for continuation 0x7fcdb402ff70
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - token=0x7fcdb402ff70: token with stream-id 1, purged from the stream table
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb402ed60: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb402ed60: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-loop] - id=0x7fcdb402ed60: Starting event-loop thread.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [dns] - id=0x7fcdb401ccc0: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-loop] - id=0x7fcdb402ed60: main loop started
[INFO] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-loop] - id=0x7fcdb402ed60: default timeout 100000, and max events to process per tick 100
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [channel-bootstrap] - id=0x7fcdb4039d10: Initializing client bootstrap with event-loop group 0x7fcdb405e150
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb401d7d0 fd=21: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb401d7d0 fd=21: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb401d7d0 fd=21: beginning connect.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb401d7d0 fd=21: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:12:11Z] [00007fcdc1048700] [socket] - id=0x7fcdb401d7d0 fd=21: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdb4049bc0: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdb4049bc0: Running (null) task with <Running> status
[INFO] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [socket] - id=0x7fcdb401d7d0 fd=21: connection success
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [socket] - id=0x7fcdb401d7d0 fd=21: assigning to event loop 0x7fcdb402ed60
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4039d10: client connection on socket 0x7fcdb401d7d0 completed with error 0.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac016440: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac016440: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: no message pool is currently stored in the event-loop local storage, adding 0x7fcdac00eab0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel-bootstrap] - id=0x7fcdb4039d10: channel 0x7fcdac00e6c0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [socket-handler] - id=0x7fcdac00df60: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: on_channel_setup_fn invoked with error_code 0 with channel 0x7fcdac00e6c0
[INFO] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - static: new handler is 0x7fcdac032c60
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: successful event-stream channel setup 0x7fcdac00e6c0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c001020: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: beginning shutdown process
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: handler 0x7fcd9c011cb0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: handler 0x7fcd9c01fb60 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c000e88: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c000e88: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: handler 0x7fcd9c01fb60 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [socket] - id=0x7fcdb4023120 fd=18: closing
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c0057c0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c011d50: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c0057c0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c011d50: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: handler 0x7fcd9c011cb0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c000e88: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c000e88: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: channel 0x7fcd9c000e60 shutdown with error 0.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7fcd9c000e60
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: releasing bootstrap reference
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-rpc-client] - id=0x7fcdb4033630: destroying connection.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: releasing bootstrap reference
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel] - id=0x7fcd9c000e60: destroying channel.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-stream-channel-handler] - id=0x7fcd9c01fb60: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: releasing bootstrap reference
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [channel-bootstrap] - id=0x7fcdb403b890: destroying
[INFO] [2022-09-16T18:12:11Z] [00007fcdb37fe700] [event-loop] - id=0x7fcdb4017d00: Destroying event_loop
[INFO] [2022-09-16T18:12:11Z] [00007fcdb37fe700] [event-loop] - id=0x7fcdb4017d00: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdb4033c98: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcdb4033c98: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [event-loop] - id=0x7fcdb4017d00: exiting main loop
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb3fff700] [task-scheduler] - id=0x7fcd9c011b40: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: read total message length of 71
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb37fe700] [task-scheduler] - id=0x7fcd9c011b40: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb406da30: continuation created 0x7fcdb402e270
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb402e270: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb406da30: operation name specified aws.greengrass#UpdateThingShadow
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: calculated prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: read total message length of 748
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: read prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-rpc-client] - id=0x7fcdb406da30:end stream flag was specified on continuation 0x7fcdb402e270
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: calculated prelude CRC of 85094772
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: read total message length of 400
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-channel-handler] - id=0x7fcdb4011560: read prelude CRC of 85094772
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdc1048700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: the terminate stream flag was specified for continuation 0x7fcdb402e270
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - token=0x7fcdb402e270: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e880: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: beginning shutdown process
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: handler 0x7fcdac00df60 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-channel-handler] - id=0x7fcdac032c60: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [channel] - id=0x7fcdac00e6c0: handler 0x7fcdac032c60 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac00e6e8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [task-scheduler] - id=0x7fcdac011e40: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - id=0x7fcdb406da30: the end stream flag was set, closing continuation 0x7fcdb402e270.
[DEBUG] [2022-09-16T18:12:11Z] [00007fcdb2ffd700] [event-stream-rpc-client] - token=0x7fcdb402e270: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-channel-handler] - id=0x7f55ec0116e0: calculated prelude CRC of 1987978345
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-channel-handler] - id=0x7f55ec0116e0: read total message length of 169
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-channel-handler] - id=0x7f55ec0116e0: read prelude CRC of 1987978345
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:12:12Z] [00007f55fd06f700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 304
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0001030: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0001030: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0001030: Starting event-loop thread.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [dns] - id=0x7f55f001f1b0: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0033650: Initializing client bootstrap with event-loop group 0x7f55f001e520
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f001d370 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f001d370 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f001d370 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f001d370 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f001d370 fd=18: connected immediately, not scheduling timeout.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0001030: main loop started
[INFO] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0001030: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f001d9e0: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f001d9e0: Running (null) task with <Running> status
[INFO] [2022-09-16T18:13:11Z] [00007f55fe071700] [socket] - id=0x7f55f001d370 fd=18: connection success
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [socket] - id=0x7f55f001d370 fd=18: assigning to event loop 0x7f55f0001030
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: client connection on socket 0x7f55f001d370 completed with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001420: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001420: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55e00016c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: channel 0x7f55e00010d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [socket-handler] - id=0x7f55e00122e0: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55e00010d0
[INFO] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - static: new handler is 0x7f55e0011ce0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: successful event-stream channel setup 0x7f55e00010d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55ec000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55ec000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: read total message length of 71
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0033fe0: continuation created 0x7f55f004bb00
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f004bb00: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0033fe0: operation name specified aws.greengrass#GetThingShadow
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55ec000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55ec000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: calculated prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: read total message length of 841
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: read prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: the terminate stream flag was specified for continuation 0x7f55f004bb00
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - token=0x7f55f004bb00: token with stream-id 1, purged from the stream table
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0021340: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0021340: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0021340: Starting event-loop thread.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [dns] - id=0x7f55f0032af0: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0021340: main loop started
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f003bc30: Initializing client bootstrap with event-loop group 0x7f55f001e580
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0021340: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0033db0 fd=21: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0033db0 fd=21: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0033db0 fd=21: beginning connect.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0033db0 fd=21: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0033db0 fd=21: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001d570: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001d570: Running (null) task with <Running> status
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0033db0 fd=21: connection success
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0033db0 fd=21: assigning to event loop 0x7f55f0021340
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: client connection on socket 0x7f55f0033db0 completed with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4009380: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4009380: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55f40010c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: channel 0x7f55f40008d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [socket-handler] - id=0x7f55f40116e0: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55f40008d0
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - static: new handler is 0x7f55f401b120
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: successful event-stream channel setup 0x7f55f40008d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: beginning shutdown process
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: handler 0x7f55e00122e0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0011ce0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e00010f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e00010f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000d40: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000d40: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0011ce0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [socket] - id=0x7f55f001d370 fd=18: closing
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0000f60: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012380: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0000f60: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012380: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: handler 0x7f55e00122e0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e00010f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e00010f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: channel 0x7f55e00010d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55e00010d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0033fe0: destroying connection.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel] - id=0x7f55e00010d0: destroying channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55e0011ce0: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0033650: destroying
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0001030: Destroying event_loop
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0001030: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0033198: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0033198: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0001030: exiting main loop
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0000de0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55e0000de0: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: read total message length of 71
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0034090: continuation created 0x7f55f00212d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00212d0: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0034090: operation name specified aws.greengrass#UpdateThingShadow
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000d40: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000d40: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: calculated prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: read total message length of 748
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: read prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: the terminate stream flag was specified for continuation 0x7f55f00212d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - token=0x7f55f00212d0: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 85094772
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 400
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 85094772
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: beginning shutdown process
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: handler 0x7f55f40116e0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: handler 0x7f55f401b120 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: handler 0x7f55f401b120 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0033db0 fd=21: closing
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4011580: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4011780: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4011580: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4011780: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: handler 0x7f55f40116e0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: channel 0x7f55f40008d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55f40008d0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f0034090: destroying connection.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel] - id=0x7f55f40008d0: destroying channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55f401b120: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f003bc30: destroying
[INFO] [2022-09-16T18:13:11Z] [00007f55fd870700] [event-loop] - id=0x7f55f0021340: Destroying event_loop
[INFO] [2022-09-16T18:13:11Z] [00007f55fd870700] [event-loop] - id=0x7f55f0021340: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f0033d58: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f0033d58: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0021340: exiting main loop
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f4000c40: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000c40: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f004a050: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f004a050: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f004a050: Starting event-loop thread.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [dns] - id=0x7f55f0034220: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f004a050: main loop started
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f004a050: default timeout 100000, and max events to process per tick 100
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f001d530: Initializing client bootstrap with event-loop group 0x7f55f001d960
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:13:11Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f0049d60: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f0049d60: Running (null) task with <Running> status
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [socket] - id=0x7f55f0030330 fd=18: connection success
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [socket] - id=0x7f55f0030330 fd=18: assigning to event loop 0x7f55f004a050
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: client connection on socket 0x7f55f0030330 completed with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001820: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001820: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: no message pool is currently stored in the event-loop local storage, adding 0x7f55d8001b90 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: channel 0x7f55d8001400 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [socket-handler] - id=0x7f55d80127b0: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55d8001400
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - static: new handler is 0x7f55d800e0a0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: successful event-stream channel setup 0x7f55d8001400
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ba0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ba0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: read total message length of 71
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00335a0: continuation created 0x7f55f002f300
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f002f300: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00335a0: operation name specified aws.greengrass#PublishToIoTCore
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ba0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ba0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: calculated prelude CRC of 658570020
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: read total message length of 167
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: read prelude CRC of 658570020
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: the terminate stream flag was specified for continuation 0x7f55f002f300
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - token=0x7f55f002f300: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80015c0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: beginning shutdown process
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: handler 0x7f55d80127b0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: handler 0x7f55d800e0a0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001428: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001428: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: handler 0x7f55d800e0a0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [socket] - id=0x7f55f0030330 fd=18: closing
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000dc0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8012850: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000dc0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8012850: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: handler 0x7f55d80127b0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001428: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8001428: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: channel 0x7f55d8001400 shutdown with error 0.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55d8001400
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f00335a0: destroying connection.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel] - id=0x7f55d8001400: destroying channel.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d800e0a0: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: releasing bootstrap reference
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f001d530: destroying
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f004a050: Destroying event_loop
[INFO] [2022-09-16T18:13:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f004a050: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f004b948: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f004b948: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f004a050: exiting main loop
[DEBUG] [2022-09-16T18:13:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ea0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:13:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55d8000ea0: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 304
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035620: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035620: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035620: Starting event-loop thread.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [dns] - id=0x7f55f00340a0: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-loop] - id=0x7f55f0035620: main loop started
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0001030: Initializing client bootstrap with event-loop group 0x7f55f0033d70
[INFO] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-loop] - id=0x7f55f0035620: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0018900 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0018900 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0018900 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0018900 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0018900 fd=18: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f001d960: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f001d960: Running (null) task with <Running> status
[INFO] [2022-09-16T18:14:12Z] [00007f55fd870700] [socket] - id=0x7f55f0018900 fd=18: connection success
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [socket] - id=0x7f55f0018900 fd=18: assigning to event loop 0x7f55f0035620
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: client connection on socket 0x7f55f0018900 completed with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f400d4c0: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f400d4c0: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55f40010c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: channel 0x7f55f40008d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [socket-handler] - id=0x7f55f4011f30: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55f40008d0
[INFO] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - static: new handler is 0x7f55f4023360
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: successful event-stream channel setup 0x7f55f40008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55d8000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55d8000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: read total message length of 71
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0035ea0: continuation created 0x7f55f0077830
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0077830: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0035ea0: operation name specified aws.greengrass#GetThingShadow
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55d8000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55d8000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: calculated prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: read total message length of 841
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: read prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: the terminate stream flag was specified for continuation 0x7f55f0077830
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - token=0x7f55f0077830: token with stream-id 1, purged from the stream table
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f003b1c0: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f003b1c0: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f003b1c0: Starting event-loop thread.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [dns] - id=0x7f55f0042240: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-loop] - id=0x7f55f003b1c0: main loop started
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-loop] - id=0x7f55f003b1c0: default timeout 100000, and max events to process per tick 100
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f003be50: Initializing client bootstrap with event-loop group 0x7f55f0048d50
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: beginning connect.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f003e7a0: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f003e7a0: Running (null) task with <Running> status
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [socket] - id=0x7f55f003b700 fd=21: connection success
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [socket] - id=0x7f55f003b700 fd=21: assigning to event loop 0x7f55f003b1c0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: client connection on socket 0x7f55f003b700 completed with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000dc0: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000dc0: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55d80136a0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: channel 0x7f55d80008d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [socket-handler] - id=0x7f55d8001000: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55d80008d0
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - static: new handler is 0x7f55d8005ea0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: successful event-stream channel setup 0x7f55d80008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: beginning shutdown process
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: handler 0x7f55f4011f30 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: handler 0x7f55f4023360 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000d20: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000d20: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: handler 0x7f55f4023360 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [socket] - id=0x7f55f0018900 fd=18: closing
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f401b140: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4011fd0: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f401b140: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4011fd0: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: handler 0x7f55f4011f30 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: channel 0x7f55f40008d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55f40008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-rpc-client] - id=0x7f55f0035ea0: destroying connection.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel] - id=0x7f55f40008d0: destroying channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: read total message length of 71
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-stream-channel-handler] - id=0x7f55f4023360: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [channel-bootstrap] - id=0x7f55f0001030: destroying
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0036f10: continuation created 0x7f55f00349e0
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-loop] - id=0x7f55f0035620: Destroying event_loop
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-loop] - id=0x7f55f0035620: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f0034048: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00349e0: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0036f10: operation name specified aws.greengrass#UpdateThingShadow
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f0034048: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [event-loop] - id=0x7f55f0035620: exiting main loop
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fd870700] [task-scheduler] - id=0x7f55f4011580: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000d20: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000d20: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: calculated prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: read total message length of 748
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: read prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: the terminate stream flag was specified for continuation 0x7f55f00349e0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - token=0x7f55f00349e0: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: beginning shutdown process
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8001000 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8005ea0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 85094772
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 400
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 85094772
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8005ea0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [socket] - id=0x7f55f003b700 fd=21: closing
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d800e0c0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80010a0: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d800e0c0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80010a0: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8001000 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d80008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: channel 0x7f55d80008d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55d80008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-rpc-client] - id=0x7f55f0036f10: destroying connection.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel] - id=0x7f55d80008d0: destroying channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-stream-channel-handler] - id=0x7f55d8005ea0: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [channel-bootstrap] - id=0x7f55f003be50: destroying
[INFO] [2022-09-16T18:14:12Z] [00007f55e6efd700] [event-loop] - id=0x7f55f003b1c0: Destroying event_loop
[INFO] [2022-09-16T18:14:12Z] [00007f55e6efd700] [event-loop] - id=0x7f55f003b1c0: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4011580: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f0030478: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f0030478: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-loop] - id=0x7f55f003b1c0: exiting main loop
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55d8000ea0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000ea0: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0064f60: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0064f60: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-loop] - id=0x7f55f0064f60: Starting event-loop thread.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [dns] - id=0x7f55f003be50: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-loop] - id=0x7f55f0064f60: main loop started
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0034490: Initializing client bootstrap with event-loop group 0x7f55f003c850
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-loop] - id=0x7f55f0064f60: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:14:12Z] [00007f55fe872700] [socket] - id=0x7f55f0030330 fd=18: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0032c90: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0032c90: Running (null) task with <Running> status
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [socket] - id=0x7f55f0030330 fd=18: connection success
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [socket] - id=0x7f55f0030330 fd=18: assigning to event loop 0x7f55f0064f60
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: client connection on socket 0x7f55f0030330 completed with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4009380: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4009380: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55f40010c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: channel 0x7f55f40008d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [socket-handler] - id=0x7f55f400d750: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55f40008d0
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - static: new handler is 0x7f55f401b120
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: successful event-stream channel setup 0x7f55f40008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012320: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012320: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: read total message length of 71
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0035ea0: continuation created 0x7f55f003b860
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f003b860: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0035ea0: operation name specified aws.greengrass#PublishToIoTCore
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012320: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55e0012320: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: calculated prelude CRC of 658570020
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: read total message length of 167
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: read prelude CRC of 658570020
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: the terminate stream flag was specified for continuation 0x7f55f003b860
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - token=0x7f55f003b860: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: beginning shutdown process
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: handler 0x7f55f400d750 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: handler 0x7f55f401b120 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: handler 0x7f55f401b120 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [socket] - id=0x7f55f0030330 fd=18: closing
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f400d4c0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f400d7f0: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f400d4c0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f400d7f0: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: handler 0x7f55f400d750 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: channel 0x7f55f40008d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55f40008d0
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0035ea0: destroying connection.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel] - id=0x7f55f40008d0: destroying channel.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f401b120: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: releasing bootstrap reference
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0034490: destroying
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0064f60: Destroying event_loop
[INFO] [2022-09-16T18:14:12Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0064f60: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0018a48: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0018a48: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [event-loop] - id=0x7f55f0064f60: exiting main loop
[DEBUG] [2022-09-16T18:14:12Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4017000: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:14:12Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f4017000: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 304
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 1966468834
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0033000: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0033000: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0033000: Starting event-loop thread.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [dns] - id=0x7f55f0032920: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0020d60: Initializing client bootstrap with event-loop group 0x7f55f003e7a0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f004bac0 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f004bac0 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f004bac0 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f004bac0 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f004bac0 fd=18: connected immediately, not scheduling timeout.
[INFO] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-loop] - id=0x7f55f0033000: main loop started
[INFO] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-loop] - id=0x7f55f0033000: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f003c850: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f003c850: Running (null) task with <Running> status
[INFO] [2022-09-16T18:15:11Z] [00007f55e6efd700] [socket] - id=0x7f55f004bac0 fd=18: connection success
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [socket] - id=0x7f55f004bac0 fd=18: assigning to event loop 0x7f55f0033000
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: client connection on socket 0x7f55f004bac0 completed with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8012200: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8012200: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55d80136a0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: channel 0x7f55d80008d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [socket-handler] - id=0x7f55d80125b0: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55d80008d0
[INFO] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - static: new handler is 0x7f55d8018220
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: successful event-stream channel setup 0x7f55d80008d0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f4011f70: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f4011f70: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: read total message length of 71
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f004a070: continuation created 0x7f55f001efd0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f001efd0: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f004a070: operation name specified aws.greengrass#GetThingShadow
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f4011f70: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f4011f70: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: calculated prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: read total message length of 841
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: read prelude CRC of 3746780417
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: the terminate stream flag was specified for continuation 0x7f55f001efd0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - token=0x7f55f001efd0: token with stream-id 1, purged from the stream table
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0036a70: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0036a70: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0036a70: Starting event-loop thread.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [dns] - id=0x7f55f0042240: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0036a70: main loop started
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0036970: Initializing client bootstrap with event-loop group 0x7f55f001f160
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0036a70: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: beginning connect.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f003b700 fd=21: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f00361a0: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f00361a0: Running (null) task with <Running> status
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [socket] - id=0x7f55f003b700 fd=21: connection success
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [socket] - id=0x7f55f003b700 fd=21: assigning to event loop 0x7f55f0036a70
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: client connection on socket 0x7f55f003b700 completed with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4009380: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4009380: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: no message pool is currently stored in the event-loop local storage, adding 0x7f55f40010c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: channel 0x7f55f40123f0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [socket-handler] - id=0x7f55f4012920: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55f40123f0
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - static: new handler is 0x7f55f402f660
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: successful event-stream channel setup 0x7f55f40123f0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8000a90: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: beginning shutdown process
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: handler 0x7f55d80125b0 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8018220 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d80008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d80008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000ec0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000ec0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: handler 0x7f55d8018220 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [socket] - id=0x7f55f004bac0 fd=18: closing
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d800e0c0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8012650: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d800e0c0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8012650: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: handler 0x7f55d80125b0 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d80008f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d80008f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: channel 0x7f55d80008d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55d80008d0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: read total message length of 71
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-rpc-client] - id=0x7f55f004a070: destroying connection.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel] - id=0x7f55d80008d0: destroying channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-stream-channel-handler] - id=0x7f55d8018220: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [channel-bootstrap] - id=0x7f55f0020d60: destroying
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0021220: continuation created 0x7f55f006c7b0
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0033000: Destroying event_loop
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0033000: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f006c7b0: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f0021220: operation name specified aws.greengrass#UpdateThingShadow
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f0064f08: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55f0064f08: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [event-loop] - id=0x7f55f0033000: exiting main loop
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e6efd700] [task-scheduler] - id=0x7f55d8005ec0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000ec0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4000ec0: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55d8005ec0: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: calculated prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: read total message length of 748
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: read prelude CRC of 3701629645
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: the terminate stream flag was specified for continuation 0x7f55f006c7b0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - token=0x7f55f006c7b0: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: calculated prelude CRC of 85094772
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read total message length of 400
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-channel-handler] - id=0x7f55f0011560: read prelude CRC of 85094772
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - message flags header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40125b0: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: beginning shutdown process
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: handler 0x7f55f4012920 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: handler 0x7f55f402f660 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4012418: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4012418: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: handler 0x7f55f402f660 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [socket] - id=0x7f55f003b700 fd=21: closing
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f401b140: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40129c0: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f401b140: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f40129c0: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: handler 0x7f55f4012920 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4012418: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4012418: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: channel 0x7f55f40123f0 shutdown with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55f40123f0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-rpc-client] - id=0x7f55f0021220: destroying connection.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel] - id=0x7f55f40123f0: destroying channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-stream-channel-handler] - id=0x7f55f402f660: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [channel-bootstrap] - id=0x7f55f0036970: destroying
[INFO] [2022-09-16T18:15:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0036a70: Destroying event_loop
[INFO] [2022-09-16T18:15:11Z] [00007f55e76fe700] [event-loop] - id=0x7f55f0036a70: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0035138: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f0035138: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0036a70: exiting main loop
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe071700] [task-scheduler] - id=0x7f55f4017000: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55e76fe700] [task-scheduler] - id=0x7f55f4017000: Running epoll_event_loop_unsubscribe_cleanup task with <Canceled> status
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035e20: Initializing edge-triggered epoll
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035e20: Using eventfd for cross-thread notifications.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-loop] - id=0x7f55f0035e20: Starting event-loop thread.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [dns] - id=0x7f55f003be70: Initializing default host resolver with 16 max host entries.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [channel-bootstrap] - id=0x7f55f0012380: Initializing client bootstrap with event-loop group 0x7f55f003c850
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0035e20: main loop started
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f0047390 fd=18: initializing with domain 2 and type 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f0047390 fd=18: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0035e20: default timeout 100000, and max events to process per tick 100
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f0047390 fd=18: beginning connect.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f0047390 fd=18: connecting to endpoint /greengrass/v2/ipc.socket:0.
[INFO] [2022-09-16T18:15:11Z] [00007f55fe872700] [socket] - id=0x7f55f0047390 fd=18: connected immediately, not scheduling timeout.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001f160: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001f160: Running (null) task with <Running> status
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0047390 fd=18: connection success
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0047390 fd=18: assigning to event loop 0x7f55f0035e20
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: client connection on socket 0x7f55f0047390 completed with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: Beginning creation and setup of new channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000f60: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000f60: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: setup complete, notifying caller.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: no message pool is currently stored in the event-loop local storage, adding 0x7f55e00016c0 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: channel 0x7f55e00010d0 setup succeeded: bootstrapping.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [socket-handler] - id=0x7f55e0013400: Socket handler created with max_read_size of 16384
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: on_channel_setup_fn invoked with error_code 0 with channel 0x7f55e00010d0
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - static: creating new event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - static: new handler is 0x7f55e0018b60
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: successful event-stream channel setup 0x7f55e00010d0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: sending connect message, waiting on connect ack
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: calculated prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: read total message length of 71
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: read prelude CRC of 927792703
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - message type header value 5
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - message flags header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - stream id header value 0
[INFO] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: connect ack received, connection handshake completed
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00777c0: continuation created 0x7f55f002ffe0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f002ffe0: continuation's new stream id is 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fe872700] [event-stream-rpc-client] - id=0x7f55f00777c0: operation name specified aws.greengrass#PublishToIoTCore
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000c60: Scheduling socket_written_task task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0000c60: Running socket_written_task task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: calculated prelude CRC of 658570020
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: read total message length of 167
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: read prelude CRC of 658570020
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :content-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name service-model-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-type
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - message type header value 0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :message-flags
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - message flags header value 2
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - processing header name :stream-id
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-general] - stream id header value 1
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: the terminate stream flag was specified for continuation 0x7f55f002ffe0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - token=0x7f55f002ffe0: token with stream-id 1, purged from the stream table
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Scheduling schedule_cross_thread_tasks task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0001290: Running schedule_cross_thread_tasks task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: beginning shutdown process
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0013400 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0018b60 shutdown in read dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00010f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00010f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: shutdown called on event-stream channel handler with error aws-c-common: AWS_ERROR_SUCCESS, Success..
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0018b60 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [socket] - id=0x7f55f0047390 fd=18: closing
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0011d00: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00134a0: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e0011d00: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00134a0: Running socket_handler_close task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: handler 0x7f55e0013400 shutdown in write dir completed.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00010f8: Scheduling (null) task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55e00010f8: Running (null) task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: channel 0x7f55e00010d0 shutdown with error 0.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: on_channel_shutdown_fn invoked with error_code 0 with channel 0x7f55e00010d0
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-rpc-client] - id=0x7f55f00777c0: destroying connection.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel] - id=0x7f55e00010d0: destroying channel.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-stream-channel-handler] - id=0x7f55e0018b60: destroying event-stream message channel handler.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: releasing bootstrap reference
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [channel-bootstrap] - id=0x7f55f0012380: destroying
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0035e20: Destroying event_loop
[INFO] [2022-09-16T18:15:11Z] [00007f55fe071700] [event-loop] - id=0x7f55f0035e20: Stopping event-loop thread.
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001d108: Scheduling epoll_event_loop_stop task for immediate execution
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [task-scheduler] - id=0x7f55f001d108: Running epoll_event_loop_stop task with <Running> status
[DEBUG] [2022-09-16T18:15:11Z] [00007f55fc86e700] [event-loop] - id=0x7f55f0035e20: exiting main loop

Sorry for the extreme verbosity

MikeDombo commented 2 years ago

@jfduque

The code example you provided is the complete code that you're using? If so, there is nothing in that snippet which will keep the main thread running. This means that just as soon as the subscribe request is sent, the process will exit.

So, 2 things to do.

1 use the v2 Greengrass IPC client. https://aws.github.io/aws-iot-device-sdk-python-v2/awsiot/greengrasscoreipc.html#awsiot.greengrasscoreipc.clientv2.GreengrassCoreIPCClientV2.subscribe_to_iot_core

https://docs.aws.amazon.com/greengrass/v2/developerguide/interprocess-communication.html#ipc-client-versions

  1. Keep the main thread alive somehow. You can do this by sleeping in a loop for example. Or by waiting for a threading.condition.
jfduque commented 2 years ago

@jfduque

The code example you provided is the complete code that you're using? If so, there is nothing in that snippet which will keep the main thread running. This means that just as soon as the subscribe request is sent, the process will exit.

So, 2 things to do.

1 use the v2 Greengrass IPC client. https://aws.github.io/aws-iot-device-sdk-python-v2/awsiot/greengrasscoreipc.html#awsiot.greengrasscoreipc.clientv2.GreengrassCoreIPCClientV2.subscribe_to_iot_core

https://docs.aws.amazon.com/greengrass/v2/developerguide/interprocess-communication.html#ipc-client-versions

  1. Keep the main thread alive somehow. You can do this by sleeping in a loop for example. Or by waiting for a threading.condition.

A couple considerations:

  1. As many other code examples in AWS docs & Github repos, some code is needed to keep the main thread running. In my case is: 
    # Keep the main thread alive, or the process will exit.
while True:
time.sleep(10)
  2. What would be the correct way to declare two handlers for two independent topics? If I use the above code two or more times, is there a chance that this will cause a conflict? Because that's just what I'm doing.

Thanks to your link I just found out that there is a GreengrassCoreIPCClientV2. I will update my code and report results.

Thanks in advance!

MikeDombo commented 2 years ago

The V2 client uses the same underlying code as the V1 client, but it does make it simpler to use and simpler to use correctly. It is absolutely recommended to use the V2 client.

Multiple handlers for the same or different topics is absolutely fine. Just call the subscribe api for each topic you want to subscribe to.

Can you include the full code including the sleeping loop?

jfduque commented 2 years ago

Looks like it's fixed in 0.14.7, thanks @bretambrose