Memory allocation problem after successive MQTT connections with TLS

[Yago-Caetano]

After repeated mqtt connection-disconnection processes,I have the problem of code -12 and it is impossible to connect with the MQTT broker after that, the issue is similar to this post.

The mqtt connection code was based on the google_iot_mqtt example because we were using "GCP IoT Core" as a broker at the beginning of the project development.

I was able to verify in the debug logs that the error is thrown in the mbed TLS library as you can see in the log below.

00> [00:02:35.804,199] <inf> my_mqtt:   Acquired time:  4 -  9 - 2022 11 :  7
00> [00:02:35.804,199] <inf> my_mqtt: ntp time got successfully
00> [00:02:38.399,017] <inf> my_mqtt: Connecting to host: <omitted>
00> [00:02:38.399,200] <dbg> net_sock_tls: tls_alloc: (): Allocated TLS context, 0x20006bb8
00> [00:02:38.399,566] <dbg> net_sock: zsock_socket_internal: (): socket: ctx=0x20007838, fd=1
00> [00:02:39.043,365] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1814: |2| ssl->f_send() returned 114 (-0xffffff8e)
00> 
00> --- 12 messages dropped ---
00> [00:02:39.043,426] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1842: |2| <= flush output
00> 
00> [00:02:39.043,487] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:2514: |2| <= write record
00> 
00> [00:02:39.043,548] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:2346: |2| <= write handshake message
00> 
00> [00:02:39.043,609] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:1346: |2| <= write client hello
00> 
00> [00:02:39.043,670] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1789: |2| => flush output
00> 
00> [00:02:39.043,731] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1801: |2| <= flush output
00> 
00> [00:02:39.043,792] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:4192: |2| client state: 2
00> 
00> [00:02:39.043,853] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:1919: |2| => parse server hello
00> 
00> [00:02:39.043,914] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:3546: |2| => read record
00> 
00> [00:02:39.043,975] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1573: |2| => fetch input
00> 
00> [00:02:39.044,067] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1728: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.807,617] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:4192: |2| client state: 3
00> 
00> --- 14 messages dropped ---
00> [00:02:39.807,678] <dbg> net_sock_tls: tls_debug: (): ssl_tls.c:2291: |2| => parse certificate
00> 
00> [00:02:39.807,739] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:3546: |2| => read record
00> 
00> [00:02:39.807,800] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1573: |2| => fetch input
00> 
00> [00:02:39.807,891] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1728: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.808,013] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.808,135] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)
00> 
00> [00:02:39.808,197] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1776: |2| <= fetch input
00> 
00> [00:02:39.808,258] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1573: |2| => fetch input
00> 
00> [00:02:39.808,319] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1728: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.808,502] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.808,624] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 244 (-0xffffff0c)
00> 
00> [00:02:39.944,793] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20007838, pkt=0x200213fc, st=0, user_data=(nil)
00> [00:02:39.951,324] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:39.951,446] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 341 (-0xfffffeab)
00> 
00> [00:02:40.356,781] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20007838, pkt=0x200213fc, st=0, user_data=(nil)
00> [00:02:40.362,792] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:40.362,915] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 341 (-0xfffffeab)
00> 
00> [00:02:40.496,673] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20007838, pkt=0x200213fc, st=0, user_data=(nil)
00> [00:02:40.502,624] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:40.502,716] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 341 (-0xfffffeab)
00> 
00> [00:02:40.838,104] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20007838, pkt=0x200213fc, st=0, user_data=(nil)
00> [00:02:40.843,963] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1753: |2| in_left: zu, nb_want: zu
00> 
00> [00:02:40.844,085] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 341 (-0xfffffeab)
00> 
00> [00:02:41.363,220] <dbg> net_sock_tls: tls_debug: (): ssl_tls.c:1769: |2| <= write certificate
00> 
00> --- 61 messages dropped ---
00> [00:02:41.363,281] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1789: |2| => flush output
00> 
00> [00:02:41.363,342] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:1801: |2| <= flush output
00> 
00> [00:02:41.363,403] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:4192: |2| client state: 8
00> 
00> [00:02:41.363,464] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:3488: |2| => write client key exchange
00> 
00> [00:02:41.388,488] <dbg> net_sock_tls: tls_debug: (): ssl_cli.c:2730: |1| mbedtls_rsa_pkcs1_encrypt() returned -17040 (-0x4290)
00> 
00> [00:02:41.388,549] <dbg> net_sock_tls: tls_debug: (): ssl_tls.c:5323: |2| <= handshake
00> 
00> [00:02:41.388,549] <err> net_sock_tls: TLS handshake error: -4290
00> [00:02:41.393,859] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20006bb8, fd=0
00> [00:02:41.393,920] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:5378: |2| => write close notify
00> 
00> [00:02:41.393,981] <dbg> net_sock_tls: tls_debug: (): ssl_msg.c:5394: |2| <= write close notify
00> 
00> [00:02:41.399,475] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20007838, fd=1
00> [00:02:41.399,536] <err> my_mqtt: could not connect, error -113
00> [00:02:44.964,019] <inf> my_mqtt: Connecting to host: <omitted>
00> [00:02:44.964,202] <dbg> net_sock_tls: tls_alloc: (): Allocated TLS context, 0x20006bb8
00> [00:02:44.964,599] <dbg> net_sock: zsock_socket_internal: (): socket: ctx=0x20007838, fd=1
00> [00:02:45.578,674] <dbg> net_sock_tls: tls_debug: (): ssl_tls.c:3280: |1| alloc(zu bytes) failed
00> 
00> [00:02:45.578,704] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20006bb8, fd=0
00> [00:02:45.579,254] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20007838, fd=1
00> [00:02:45.585,144] <err> my_mqtt: could not connect, error -12
00> [00:02:49.154,113] <inf> my_mqtt: Connecting to host: <omitted>
00> [00:02:49.154,296] <dbg> net_sock_tls: tls_alloc: (): Allocated TLS context, 0x20006bb8
00> [00:02:49.154,663] <dbg> net_sock: zsock_socket_internal: (): socket: ctx=0x20007838, fd=1
00> [00:02:49.737,396] <dbg> net_sock_tls: tls_debug: (): ssl_tls.c:3280: |1| alloc(zu bytes) failed
00> 
00> [00:02:49.737,426] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20006bb8, fd=0
00> [00:02:49.737,976] <dbg> net_sock: z_impl_zsock_close: (): close: ctx=0x20007838, fd=1
00> [00:02:49.743,774] <err> my_mqtt: could not connect, error -12

Also, I'm attaching the code snippet used in the MQTT communication

void mqtt_startup()
{
	mqttRetries = 5;

	broker4 = (struct sockaddr_in *)&broker;
	client = &client_ctx;

    if(my_mqtt_useTls && my_mqtt_first_exec)
    {
        err = tls_credential_add(1, TLS_CREDENTIAL_CA_CERTIFICATE,
                    my_ca_certificate,
                    sizeof(my_ca_certificate));


        if ((err < 0) && (err != -EEXIST)) {
            LOG_ERR("Failed to register public certificate: %d", err);
        }

		my_mqtt_first_exec = false;
    }



	while (mqttRetries) 
	{
		if(k_sem_take(&my_mqtt_sem_disconnect,K_NO_WAIT) == 0)
		{
			//should stop connection process
			return;
		}

		hints.ai_family = AF_INET;
		hints.ai_socktype = SOCK_STREAM;
		hints.ai_protocol = 0;
		dnssCnt = 0;
		
		#ifndef CONFIG_MQTT_HOST_USE_HOST_WITHOUT_DNS

		while ((err = getaddrinfo(my_broker_address, my_broker_port, &hints,
					  &haddr)) && dnssCnt < 3)
		{
			LOG_ERR("Unable to get address for broker, retrying");
			dnssCnt++;
		}

		if (err != 0)
		{
			LOG_ERR("Unable to get address for broker, error %d",err);
			if(mqttExternalCb != NULL)
			{
				my_mqtt_cb_t params;
				params.event = MY_MQTT_CONNECTION_FAILED;
				mqttExternalCb(&params);
			}
			return;
		}
		
		LOG_INF("DNS resolved for %s:%d",my_broker_address,my_broker_port);

		net_ipaddr_copy(&broker4->sin_addr,&net_sin(haddr->ai_addr)->sin_addr);

		#else

		broker4->sin_family = AF_INET;
		broker4->sin_port = htons(my_broker_port);
		zsock_inet_pton(AF_INET, my_broker_address, &broker4->sin_addr);

		#endif
		mqtt_client_init(client);

		if(my_mqtt_useTls)
        {
            now = my_time_get_timestamp(NULL);

            err = jwt_init_builder(&jb, token, sizeof(token));
            if (err != 0) {
                LOG_ERR("Error with JWT token initialization: %d",err);
                return;
            }

            err = jwt_add_payload(&jb, now + 60 * 60, now,
                        CONFIG_CLOUD_AUDIENCE);
            if (err != 0) {
                LOG_ERR("Error with JWT token payload including: %d",err);
                return;
            }

            err = jwt_sign(&jb, zepfull_private_der,
                    zepfull_private_der_len);

            if (err != 0) {
                LOG_ERR("Error with JWT token signing: %d",err);
                return;
            }
		
        }


		/* MQTT client configuration */
		client->broker = &broker;
		client->evt_cb = mqtt_evt_handler;
		client->client_id.utf8 = client_id;
		client->client_id.size = strlen(client_id);
        client->password = &password;

        if(my_mqtt_useTls)
        {
		    password.size = jwt_payload_len(&jb);
        }
        else
        {
		    password.size = 1;

        }

		client->user_name = &username;
		client->protocol_version = MQTT_VERSION_3_1_1;

		/* MQTT buffers configuration */
		client->rx_buf = rx_buffer;
		client->rx_buf_size = sizeof(rx_buffer);
		client->tx_buf = tx_buffer;
		client->tx_buf_size = sizeof(tx_buffer);

        if(my_mqtt_useTls)
        {
            /* MQTT transport configuration */
            client->transport.type = MQTT_TRANSPORT_SECURE;


            struct mqtt_sec_config *tls_config =
                    &client->transport.tls.config;

            tls_config->peer_verify = TLS_PEER_VERIFY_OPTIONAL; 
            tls_config->cipher_list = NULL;
            tls_config->sec_tag_list = m_sec_tags;
            tls_config->sec_tag_count = ARRAY_SIZE(m_sec_tags);
            tls_config->hostname = my_broker_address;
            
        }
        else
        {
            client->transport.type = MQTT_TRANSPORT_NON_SECURE;
        }

		LOG_INF("Connecting to host: %s", my_broker_address);
		err = mqtt_connect(client);
		if (err != 0) {
			LOG_ERR("could not connect, error %d", err);
			//mqtt_disconnect(client);
			mqtt_abort(client);
			mqttRetries--;
			k_msleep(ALIVE_TIME);
			continue;
		}

		if (wait_for_input(5 * MSEC_PER_SEC) > 0) 
		{
			mqtt_input(client);
			if (!connected) 
			{
				LOG_ERR("failed to connect to mqtt_broker");
				//mqtt_disconnect(client);
				mqtt_abort(client);
				mqttRetries--;
				k_msleep(ALIVE_TIME);
				continue;
			} else {
				break;
			}
		} else {
			LOG_ERR("failed to connect to mqtt broker");
			//mqtt_disconnect(client);
			mqtt_abort(client);
			mqttRetries--;
			k_msleep(ALIVE_TIME);
			continue;
		}
	}

	if (!connected) {
		LOG_ERR("Failed to connect to client, aborting");

		if(mqttExternalCb != NULL)
		{
			my_mqtt_cb_t params;
			params.event = MY_MQTT_CONNECTION_FAILED;
			mqttExternalCb(&params);
		}

		return;
	}
	else
	{
		my_mqtt_connected = true;
	}


	mqtt_live(client);

	next_alive = k_uptime_get() + ALIVE_TIME;

	while (1) {
		
		 // check if we have mqtt message to publish
		if(k_msgq_get(&mqtt_msg_queue, &auxPubStructure, K_NO_WAIT) == 0)
		{


			/* initialize publish structure */
			pub_data.message.topic.topic.utf8 = auxPubStructure.topic;
			pub_data.message.topic.topic.size = strlen(auxPubStructure.topic);
			pub_data.message.topic.qos = MQTT_QOS_1_AT_LEAST_ONCE;
			pub_data.message.payload.data = (uint8_t *)auxPubStructure.payload;
			pub_data.message.payload.len = strlen(auxPubStructure.payload); //manual
			pub_data.message_id = 1U;
			pub_data.dup_flag = 0U;
			pub_data.retain_flag = 1U;

			LOG_INF("Publishing data");

			err = mqtt_publish(client, &pub_data);
			if (err) 
			{
				LOG_ERR("could not publish, error %d", err);
				break;
			}
			else
			{
				if(mqttExternalCb != NULL)
				{
					my_mqtt_cb_t params;
					params.event = MY_MQTT_PUBLISHED_DATA;
					mqttExternalCb(&params);
				}
			}

			memset(&auxPubStructure,0,sizeof(my_mqtt_pub_message_t));

		}

		/* idle and process messages */
		while (k_uptime_get() < next_alive) 
		{
			LOG_INF("... idling ...");
			if (wait_for_input(1 * MSEC_PER_SEC) > 0)
			{
				mqtt_input(client);
			}

			if(k_sem_take(&my_mqtt_sem_disconnect,K_NO_WAIT) == 0)
			{
				mqtt_disconnect(client);
				my_mqtt_connected = false;
				return;

			}

			if(!connected)
			{
				mqtt_abort(client);

				return;
			}
		}

		mqtt_live(client);
		next_alive += ALIVE_TIME;
	}
}

To speed up the understanding of the code, I will describe below the process executed in the mqtt_startup() function.

1. configure the mqtt client;
2. sign JWT
3. Connect to broker;
4. MQTT Idling

I'm attaching also the proj.conf file

#bluetooh
CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEVICE_NAME="MyDevice"


#Enable GPIO
CONFIG_GPIO=y

#I2C
CONFIG_I2C=y
CONFIG_NRFX_TWIM0=y

#LOG
CONFIG_LOG=y

CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n

CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n


#log
CONFIG_SERIAL=y
CONFIG_UART_INTERRUPT_DRIVEN=y

#   --- Modem and PPP ---


# GSM modem support
CONFIG_MODEM=y
CONFIG_MODEM_GSM_PPP=y

# PPP networking support
CONFIG_NET_DRIVERS=y
CONFIG_NET_PPP=y
CONFIG_NET_L2_PPP=y
CONFIG_NETWORKING=y

CONFIG_PPP_NET_IF_NO_AUTO_START=y
CONFIG_GSM_PPP_AUTOSTART=n
CONFIG_NET_CONFIG_AUTO_INIT=n


CONFIG_NET_L2_PPP_TIMEOUT=10000

# Wait milliseconds before starting ppp handshakes
CONFIG_NET_L2_PPP_DELAY_STARTUP_MS=5000

# IPv4 enables PPP IPCP support
CONFIG_NET_IPV4=y
CONFIG_NET_IPV6=n

# Network management events
CONFIG_NET_CONNECTION_MANAGER=y

CONFIG_MODEM_SIM_NUMBERS=y
CONFIG_MODEM_CELL_INFO=y

CONFIG_NET_SHELL=y
CONFIG_MODEM_SHELL=y

CONFIG_GSM_MUX=n
CONFIG_UART_MUX=n
CONFIG_MODEM_GSM_APN="virtueyes.com.br"

CONFIG_NET_L2_PPP_OPTION_MRU=y
#CONFIG_GSM_MUX_MRU_DEFAULT_LEN=1024

#PPP
CONFIG_NET_PPP_MTU_MRU=2048
CONFIG_NET_PPP_RX_STACK_SIZE=2048
CONFIG_NET_PPP_RINGBUF_SIZE=512


CONFIG_NET_TCP_WORKQ_STACK_SIZE=2048
# Log buffers, modem and PPP
CONFIG_NET_LOG=y
CONFIG_MODEM_LOG_LEVEL_DBG=y
CONFIG_NET_PPP_LOG_LEVEL_DBG=n
CONFIG_MODEM_CONTEXT_VERBOSE_DEBUG=n

#   --- END of Modem and PPP ---


#enable suport to float pointer in print functions
CONFIG_CBPRINTF_FP_SUPPORT=y



# --- MQTT ---

#select transport stacks
CONFIG_NET_UDP=y
CONFIG_NET_TCP=y
CONFIG_NET_DHCPV4=y

#jwt
CONFIG_JWT=y
CONFIG_JWT_SIGN_RSA=y

#dns
CONFIG_DNS_SERVER_IP_ADDRESSES=y
CONFIG_DNS_SERVER1="8.8.8.8"
CONFIG_DNS_RESOLVER=y
CONFIG_DNS_RESOLVER_ADDITIONAL_BUF_CTR=2

#sntp
CONFIG_SNTP=y


CONFIG_PTHREAD_IPC=n 
CONFIG_NET_SOCKETS=y
CONFIG_MQTT_LIB=y
CONFIG_MQTT_LIB_TLS=y
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=1
CONFIG_MQTT_KEEPALIVE=30

CONFIG_NET_SOCKETS_POSIX_NAMES=y


# Enable MBEDTLS
CONFIG_MBEDTLS=y
CONFIG_MBEDTLS_BUILTIN=y
CONFIG_MBEDTLS_SHELL=y


CONFIG_MBEDTLS_ENABLE_HEAP=y
CONFIG_MBEDTLS_HEAP_SIZE=56240

CONFIG_MBEDTLS_USER_CONFIG_ENABLE=y
CONFIG_MBEDTLS_USER_CONFIG_FILE="user-tls-conf.h"

CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=16384

CONFIG_MBEDTLS_DEBUG=y
CONFIG_MBEDTLS_DEBUG_LEVEL=2
CONFIG_MBEDTLS_MEMORY_DEBUG=y

CONFIG_MBEDTLS_KEY_EXCHANGE_ECDHE_ECDSA_ENABLED=y
CONFIG_MBEDTLS_ECP_ALL_ENABLED=y

CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=y


#json
CONFIG_CJSON_LIB=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y
CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_MIN_REQUIRED_HEAP_SIZE=8192


# --- END OF MQTT ---




#log
CONFIG_MODEM_LOG_LEVEL_DBG=n
CONFIG_NET_PPP_LOG_LEVEL_DBG=n
CONFIG_NET_L2_PPP_LOG_LEVEL_DBG=n
CONFIG_NET_MGMT_EVENT_LOG_LEVEL_DBG=y
CONFIG_NET_CONNECTION_MANAGER_LOG_LEVEL_DBG=n
CONFIG_NET_DHCPV4_LOG_LEVEL_DBG=n

CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y

CONFIG_MAIN_STACK_SIZE=4096


#DEBUG
CONFIG_SYS_HEAP_LISTENER=y
CONFIG_NEWLIB_LIBC_HEAP_LISTENER=y
CONFIG_SYS_HEAP_VALIDATE=y
CONFIG_SYS_HEAP_RUNTIME_STATS=y

Some considerations:

1. The code shown above is executed on a exclusive thread with priority 10 and Stack size of 8096;
2. I'm using the nRF Connect SDK 2.1.0;
3. I don't have much experience with Zephyr;
4. I'm using a nRF52840 module with Telit Modem;

I would like your guys help, and I would to know if the connect/disconnect approach that I'm doing is correct.

Regards

[Yago-Caetano]

Hello Kazi,

The problem was solved.

Is it necessary for me to register this issue there in the Zephyr project, or your guys do the register?

Thank you for your help.

Best Regards,

Yago Caetano

[Kazi Afroza Sultana]

Hello Yago, 

It's really great that your problem is fixed. Yes, that would be really helpful to other if you open a pull request with an actual fix of the bug. 

Thanks. 

Best Regards,

Kazi Afroza Sultana