Asset_tracker_v2 disconnect from AWS when shadow data is more than 2k

[Dmitry Pogodin]

Hello,

I'm using nRF SDK v1.6.0 with nRF9160 development board. I did minimum changes to Asset_Tracker_v2 application (enable debug log, set up for my aws account and to use my shadow).

After that, immediately after connecting to the cloud and requesting shadow data, application disconnect from the cloud with error code -128.

Here is a debug log:

[00:00:06.359,619] <dbg> cloud_module.connect_cloud: Connecting to cloud
[00:00:06.366,760] <wrn> cloud_module: Cloud connection establishment in progress
[00:00:06.374,908] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:00:06.384,155] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING
[00:00:06.392,791] <inf> event_manager: CLOUD_EVT_CONNECTING
[00:00:06.553,192] <dbg> aws_iot.broker_init: IPv4 Address found 16.170.78.147
%CESQ: 62,3,23,3
[00:00:09.872,772] <dbg> aws_iot.connect_client: Using send socket timeout of 60 seconds
[00:00:09.881,225] <dbg> aws_iot.aws_e[00:00:10.073,486] <dbg> aws_iot.mqtt_evt_handler: MQTT client connected!
[00:00:10.080,596] <dbg> aws_iot.topic_subscribe: Subscribing to application topic: $aws/things/---/shadow/get/accepted
[00:00:10.094,696] <dbg> aws_iot.topic_subscribe: Subscribing to AWS shadow topic: $aws/things/---/shadow/update/delta
%CESQ: 61,3,17,2
[00:00:10.270,751] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2641 result = 0
[00:00:10.489,746] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 3103 result = 0
[00:00:10.498,199] <dbg> aws_iot.0 aws_iot.device_shadow_document_request: Device shadow document requested
[00:00:10.518,676] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTED
[00:00:10.527,252] <inf> event_manager: CLOUD_EVT_CONNECTED
[00:00:10.533,721] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_DISCONNECTED --> SUB_STATE_CLOUD_CONNECTED
[00:00:10.754,211] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = -128
[00:00:10.762,420] <dbg> cloud_modulevent_handler: CLOUD_WRAP_EVT_DISCONNECTED
[00:00:10.771,270] <inf> event_manager: CLOUD_EVT_DISCONNECTED
[00:00:10.777,893] <dbg> aws_iot.aws_iot_cloud_poll: The cloud socket is already closed.
[00:00:10.786,346] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_CONNECTED --> SUB_STATE_CLOUD_DISCONNECTED
[00:00:10.798,706] <dbg> cloud_module.connect_check_work_fn: Cloud connection timeout occurred
[00:00:10.807,769] <inf> event_manager: CLOUD_EVT_CONNECTION_TIMEOUT

Here is my changes in prj.conf:

...

# # AWS IoT
# ## Mandatory application specific configurations for AWS_IOT.
CONFIG_AWS_IOT=y
CONFIG_AWS_IOT_TOPIC_UPDATE_DELTA_SUBSCRIBE=y
# CONFIG_AWS_IOT_TOPIC_GET_REJECTED_SUBSCRIBE=y
CONFIG_AWS_IOT_AUTO_DEVICE_SHADOW_REQUEST=y
CONFIG_AWS_IOT_MQTT_RX_TX_BUFFER_LEN=2048
CONFIG_AWS_IOT_MQTT_PAYLOAD_BUFFER_LEN=2048
CONFIG_AWS_IOT_APP_SUBSCRIPTION_LIST_COUNT=1
CONFIG_AWS_IOT_CLIENT_ID_APP=y
# CONFIG_AWS_FOTA=y

# ## AWS IoT options that must be configured.
CONFIG_AWS_IOT_SEC_TAG=42
CONFIG_AWS_IOT_BROKER_HOST_NAME="---.amazonaws.com"
CONFIG_AWS_IOT_CLIENT_ID_STATIC="---"
CONFIG_CLOUD_CLIENT_ID="---"
CONFIG_CLOUD_CLIENT_ID_USE_CUSTOM=y

....

# nRF Cloud
CONFIG_NRF_CLOUD=n
CONFIG_AGPS=n
CONFIG_AGPS_SRC_NRF_CLOUD=n
CONFIG_NRF_CLOUD_AGPS=n
## Because PGPS consumes a lot of data its disabled by default.
CONFIG_NRF_CLOUD_PGPS=n
CONFIG_NRF_CLOUD_CONNECTION_POLL_THREAD=n
CONFIG_NRF_CLOUD_SEND_TIMEOUT=n
CONFIG_GPS_MODULE_NMEA=n

....

CONFIG_CLOUD_CODEC_LOG_LEVEL_DBG=y
CONFIG_CLOUD_MODULE_LOG_LEVEL_DBG=y
CONFIG_AWS_IOT_LOG_LEVEL_DBG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y
CONFIG_BOOT_DELAY=3000

And changes in aws_iot_integration.c:

#define CFG_TOPIC AWS "%s/shadow/get/accepted"
#define CFG_TOPIC_LEN (AWS_LEN + AWS_CLOUD_CLIENT_ID_LEN + 20)

This problem is not related to the cloud settings as reducing shadow data size eliminate this issue. It's all about some buffer or another limit on application side.

So far I was able to trace the problem down to mqtt_client_tls_read function() from mqtt_transport_socket_tls.c file in which zsock_recv() call return 0, when shadow data was sent from AWS.

I've tried all different CONFIG_xxx_ LOG_LEVEL_DBG settings, but wasn't able to see any further information, why zsock_recv() may silently skip incoming data.

[Dmitry Pogodin]

Can it be related to:

/**@brief Maximum TLS message size in bytes. */
#define NRF_MODEM_TLS_MAX_MESSAGE_SIZE 2048

from nrfxlib/nrf_modem/include/nrf_modem_limits.h?

[Charlie]

Could be related, did you test with a bigger message size?

Best regards,

Charlie

[Dmitry Pogodin]

I can't. It's a define in header file for pre-compiled modem library.

[Charlie]

MQTT messages can be divided into several TCP packages. NRF_MODEM_TLS_MAX_MESSAGE_SIZ decides max size per message, and you can try to adjust the following parameters to adjust the max size of one MQTT message:

CONFIG_AWS_IOT_MQTT_RX_TX_BUFFER_LEN=2048
CONFIG_AWS_IOT_MQTT_PAYLOAD_BUFFER_LEN=2048

Best regards,

Charlie

[Dmitry Pogodin]

I've tried setting those two parameters for 2048 and 1024 - no visible change. Disconnect right after requested shadow data arrived.

Can it be so that AWS cloud use predefined, non negotiable TLS message size? And therefore there is no other way to fix the problem as to increase or better allow user to configure MAX TLS message size in Nordic's modem library?

PS: any way I think it will be nice to have a warning when modem/TLS library decide to reject incoming message. Also I think that have a runtime check for the two above mentioned parameters that they should be less than MAX TLS (if TLS connection is selected) can be good as well.