After Some Time Socket Getting Closed

[rana94302]

Describe the bug

[DEBUG] [2023-03-30T11:50:27Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: Received PUBACK packet
[DEBUG] [2023-03-30T11:50:27Z] [00007f25b18af700] [mqtt5-general] - id=0x7f25b18ae2d0: aws_mqtt5_packet_puback_view packet id set to 3
[DEBUG] [2023-03-30T11:50:27Z] [00007f25b18af700] [mqtt5-general] - id=0x7f25b18ae2d0: puback 0 reason code: Success
[INFO] [2023-03-30T11:50:27Z] [00007f25b18af700] [mqtt5-client] - Publish completion callback triggered.
[DEBUG] [2023-03-30T11:50:27Z] [00007f25b18af700] [task-scheduler] - id=0x7f25ac07aba0: Running Mqtt5Service task with status
[DEBUG] [2023-03-30T11:50:27Z] [00007f25b18af700] [task-scheduler] - id=0x7f25ac07aba0: Scheduling Mqtt5Service task for future execution at time 121574941865786
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [task-scheduler] - id=0x7f25ac07aba0: Running Mqtt5Service task with status
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: next PINGREQ scheduled for time 122774964312793
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: queuing PINGREQ
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: enqueuing PINGREQ operation to front
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: setting up encode for a PINGREQ packet
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [mqtt5-client] - id=0x7f25ac07ab70: finished encoding current operation
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [task-scheduler] - id=0x7f2590002460: Scheduling socket_written_task task for immediate execution
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [task-scheduler] - id=0x7f25ac07aba0: Scheduling Mqtt5Service task for future execution at time 121604964385447
[DEBUG] [2023-03-30T12:06:47Z] [00007f25b18af700] [task-scheduler] - id=0x7f2590002460: Running socket_written_task task with status
[INFO] [2023-03-30T12:07:11Z] [00007f25b18af700] [socket] - id=0x7f25900022c0 fd=21: socket is closed.
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [task-scheduler] - id=0x7f2590003910: Scheduling channel_shutdown task for immediate execution
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [channel] - id=0x7f2590003710: Channel shutdown is already pending, not scheduling another.
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [task-scheduler] - id=0x7f2590003910: Running channel_shutdown task with status
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [channel] - id=0x7f2590003710: beginning shutdown process
Mqtt5 Client disconnection with reason: aws-c-io: AWS_IO_SOCKET_CLOSED, socket is closed..
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [channel] - id=0x7f2590003710: handler 0x7f2590014560 shutdown in read dir completed.
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [tls-handler] - id=0x7f2590014690: Shutting down read direction with error code 1051
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [channel] - id=0x7f2590003710: handler 0x7f2590014690 shutdown in read dir completed.
[DEBUG] [2023-03-30T12:07:11Z] [00007f25b18af700] [channel] - id=0x7f2590003710: handler 0x7f25ac07ac38 shutdown in read dir completed.
Segmentation fault

Expected Behavior

This should be continuously connected whether mqtt is in idle state or not.

Current Behavior

After some time MQTT is getting disconnected and Socket getting closed.

Reproduction Steps

Step to reproduce:

1. Establish the connection
2. publish some data, which working fine.
3. receive some data which subscribed.
4. leave for some time more than 10 minutes in idle state
5. then automatically socket get closed and MQTT get disconnected.

Possible Solution

No response

Additional Information/Context

No response

SDK version used

aws-iot-device-sdk-cpp-v2

Environment details (OS name and version, etc.)

Ubuntu 18.04

[jmklix]

Does this happen every time? Are you running into this when running the mqtt5 pubsub sample?

At the bottom I see it's seg faulting. Are there any more logs/stack trace from that?

[rana94302]

Does this happen every time? Are you running into this when running the mqtt5 pubsub sample?

At the bottom I see it's seg faulting. Are there any more logs/stack trace from that?

yes. I am getting everytime. below are latest log after using 1.21.0. Just want to highlight below first four line which i didn't understand:

[DEBUG] [2023-03-30T13:25:06Z] [00007f3024c34700] [task-scheduler] - id=0x7f302007aca0: Running Mqtt5Service task with <Running> status
[DEBUG] [2023-03-30T13:25:06Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: connected sufficiently long that reconnect backoff delay has been reset back to minimum value
[DEBUG] [2023-03-30T13:25:06Z] [00007f3024c34700] [task-scheduler] - id=0x7f302007aca0: Scheduling Mqtt5Service task for future execution at time 127444475247240
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [task-scheduler] - id=0x7f302007aca0: Running Mqtt5Service task with <Running> status
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: next PINGREQ scheduled for time 128644475475912
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: queuing PINGREQ
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: enqueuing PINGREQ operation to front
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: setting up encode for a PINGREQ packet
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: finished encoding current operation
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100021a0: Scheduling socket_written_task task for immediate execution
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [task-scheduler] - id=0x7f302007aca0: Scheduling Mqtt5Service task for future execution at time 127474475529176
[DEBUG] [2023-03-30T13:44:36Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100021a0: Running socket_written_task task with <Running> status
[INFO] [2023-03-30T13:45:02Z] [00007f3024c34700] [socket] - id=0x7f3010002000 fd=21: socket is closed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100032b0: Scheduling channel_shutdown task for immediate execution
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: Channel shutdown is already pending, not scheduling another.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100032b0: Running channel_shutdown task with <Running> status
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: beginning shutdown process
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f30100141a0 shutdown in read dir completed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [tls-handler] - id=0x7f30100143e0: Shutting down read direction with error code 1051
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f30100143e0 shutdown in read dir completed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f302007ad38 shutdown in read dir completed.
Mqtt5 Client disconnection with reason: aws-c-io: AWS_IO_SOCKET_CLOSED, socket is closed..
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100030d8: Scheduling (null) task for immediate execution
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100030d8: Running (null) task with <Running> status
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f302007ad38 shutdown in write dir completed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f30100143e0 shutdown in write dir completed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [socket] - id=0x7f3010002000 fd=21: closing
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f3010001f80: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f3010014240: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f3010001f80: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f3010014240: Running socket_handler_close task with <Running> status
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel] - id=0x7f30100030b0: handler 0x7f30100141a0 shutdown in write dir completed.
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100030d8: Scheduling (null) task for immediate execution
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [task-scheduler] - id=0x7f30100030d8: Running (null) task with <Running> status
[DEBUG] [2023-03-30T13:45:02Z] [00007f3024c34700] [channel-bootstrap] - id=0x7f3020004490: channel 0x7f30100030b0 shutdown with error 1051.
[INFO] [2023-03-30T13:45:02Z] [00007f3024c34700] [mqtt5-client] - id=0x7f302007ac70: emitting disconnection lifecycle event with error code 1051(aws-c-io: AWS_IO_SOCKET_CLOSED, socket is closed.)
[INFO] [2023-03-30T13:45:02Z] [00007f3024c34700] [mqtt5-client] -   Error Code: 1051(aws-c-io: AWS_IO_SOCKET_CLOSED, socket is closed.)
Segmentation fault

[jmklix]

I see that you opened another issue on the js repo with the exact same into. Can you post the full logs?

[rana94302]

I see that you opened another issue on the js repo with the exact same into. Can you post the full logs?

Its same issue, I am getting in C++ probably we can delete in Js.

[rana94302]

Below latest log after did fresh installation of library:

[DEBUG] [2023-03-31T07:12:27Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35c800e5d0: Running Mqtt5Service task with status
[DEBUG] [2023-03-31T07:12:27Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: connected sufficiently long that reconnect backoff delay has been reset back to minimum value
[DEBUG] [2023-03-31T07:12:27Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35c800e5d0: Scheduling Mqtt5Service task for future execution at time 191487050725700
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35c800e5d0: Running Mqtt5Service task with status
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: next PINGREQ scheduled for time 192687154358894
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: queuing PINGREQ
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: enqueuing PINGREQ operation to front
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: setting up encode for a PINGREQ packet
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: finished encoding current operation
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35b4001150: Scheduling socket_written_task task for immediate execution
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35c800e5d0: Scheduling Mqtt5Service task for future execution at time 191517154431753
[DEBUG] [2023-03-31T07:31:57Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35b4001150: Running socket_written_task task with status
Mqtt5 Client disconnection with reason: libaws-c-mqtt: AWS_ERROR_MQTT5_PING_RESPONSE_TIMEOUT, Remote endpoint did not respond to a PINGREQ before timeout exceeded.
[DEBUG] [2023-03-31T07:32:27Z] [00007f35c5ffb700] [task-scheduler] - id=0x7f35c800e5d0: Running Mqtt5Service task with status
[INFO] [2023-03-31T07:32:27Z] [00007f35c5ffb700] [mqtt5-client] - id=0x7f35c800e5a0: emitting disconnection lifecycle event with error code 5152(libaws-c-mqtt: AWS_ERROR_MQTT5_PING_RESPONSE_TIMEOUT, Remote endpoint did not respond to a PINGREQ before timeout exceeded)
[INFO] [2023-03-31T07:32:27Z] [00007f35c5ffb700] [mqtt5-client] - Error Code: 5152(libaws-c-mqtt: AWS_ERROR_MQTT5_PING_RESPONSE_TIMEOUT, Remote endpoint did not respond to a PINGREQ before timeout exceeded)

Thread 7 "AwsEventLoop 5" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f35c5ffb700 (LWP 18620)]
__GI___pthread_once (once_control=0x1f83d9ab5be0cd31, init_routine=0x7f35ce9e33f0 <__once_proxy>) at pthread_once.c:139
139 pthread_once.c: No such file or directory.

[rana94302]

why is it emitting disconnection lifecycle event after 15 min of Idle state once connection established ? is there any time out ?
How can we make it for infinite time ?