This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Multiple connect attempts hangs on connect with AWS_IOT cloud backend

I'm using v1.2.0 for the nrf project and I am fairly confident I am using modem firmware 1.1.1 (though I don't know how to verify that).

I'm basing my project on "cloud_client" example using the aws_iot backend, and have this function setup:

static void aws_iot_test_work(struct k_work *work) {
    LOG_DBG("AWS IoT Work!");
	int err = cloud_connect(s_cloud_backend);
	if (err) {
		LOG_DBG("connect error: %d", err);
		return;
	}
	LOG_DBG("Connect success!");
	struct pollfd fds[] = {
		{
			.fd = s_cloud_backend->config->socket,
			.events = POLLIN
		}
	};
	while(1) {
        err = poll(fds, ARRAY_SIZE(fds), K_MSEC(10000));
        if (err < 0) {
            LOG_DBG("poll error!: %d", err);
            goto out_disconnect;
        }
        if (err == 0) {
            LOG_DBG("Timeout!");
            goto out_disconnect;
        }

        if ((fds[0].revents & POLLIN) == POLLIN) {
            LOG_DBG("Input!");
            cloud_input(s_cloud_backend);
        }

        if ((fds[0].revents & POLLNVAL) == POLLNVAL) {
            LOG_DBG("Socket error: POLLNVAL, the cloud socket was unexpectedly closed.");
            goto out_disconnect;
        }

        if ((fds[0].revents & POLLHUP) == POLLHUP) {
            LOG_DBG("Socket error: POLLHUP, connection was closed by the cloud.");
            goto out_disconnect;
        }

        if ((fds[0].revents & POLLERR) == POLLERR) {
            LOG_DBG("Socket error: POLLERR, cloud connection was unexpectedly closed");
            goto out_disconnect;
        }
	}

out_disconnect:
    err = cloud_disconnect(s_cloud_backend);
    if(err) {
        LOG_DBG("disconnect failure! %d", err);
    }
}

Running this function once works.  It connects, waits 10 seconds, and then disconnects just fine.

When I run it a second time though it hangs the process.  I've traced the problem to this line in "zephyr/subsys/net/lib/mqtt/mqtt_transport_socket_tls.c":

	ret = connect(client->transport.tls.sock, client->broker,
		      peer_addr_size);

After this I believe its just making calls into bsdlib which we don't have source for.

Any thoughts on what else I need to do with the mqtt_client or socket so I can reuse it?

Parents Reply Children
  • It's kicked off by a button press, so more or less immediately

    I'm attaching a log of the run with these logs enabled:

    CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y
    CONFIG_AWS_IOT_LOG_LEVEL_DBG=y
    CONFIG_NET_LOG=y
    CONFIG_MQTT_LOG_LEVEL_DBG=y

    The first run of the function starts at [00:02:09.334,716] and ends at [00:02:27.656,951] and the second run starts at [00:02:35.130,950] and hangs at the connect

    *** Booting Zephyr OS build v2.1.99-ncs1  ***
    
    
    [00:00:00.192,993] <dbg> ss_certs.ss_certs_check_type: Keys exist 0 already!
    [00:00:00.195,098] <dbg> ss_certs.ss_certs_check_type: Keys exist 1 already!
    [00:00:00.197,204] <dbg> ss_certs.ss_certs_check_type: Keys exist 2 already!
    [00:00:00.197,357] <dbg> main.main: Init Success
    [00:00:00.197,418] <dbg> ss_lte.ss_lte_connection_work: Running init work
    [00:00:00.199,707] <dbg> ss_lte.ss_lte_connection_work: Init work return 0
    [00:00:00.199,737] <dbg> main.lte_connection_cb: Init Success!
    [00:00:04.997,161] <dbg> ss_lte.ss_lte_connection_work: Running connect work
    [00:00:04.997,161] <dbg> main.lte_connection_cb: Connecting!
    [00:00:04.997,253] <dbg> lte_lc.w_lte_lc_connect: Network mode: AT%XSYSTEMMODE=1,0,0,0
    [00:01:36.097,412] <dbg> lte_lc.parse_nw_reg_status: Network registration status: 2
    [00:01:42.088,378] <dbg> lte_lc.parse_nw_reg_status: Network registration status: 5
    [00:01:42.088,562] <dbg> ss_lte.ss_lte_connection_work: Connect request return 0
    [00:01:42.088,562] <dbg> ss_lte.ss_lte_connection_work: Requesting PSM
    [00:01:42.089,813] <dbg> ss_lte.ss_lte_connection_work: PSM request ret 0
    [00:01:42.089,813] <dbg> main.lte_connection_cb: LTE Connected!
    [00:02:09.334,716] <dbg> ss_aws.aws_iot_test_work: AWS IoT Work!
    [00:02:10.252,380] <dbg> aws_iot.broker_init: IPv4 Address found 54.149.99.172
    [00:02:10.252,746] <dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20020620): Created socket 2
    [00:02:15.738,250] <dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20020620): Connect completed
    [00:02:15.738,281] <dbg> net_mqtt_enc.connect_request_encode: (0x20020620): Encoding Protocol Description. Str:MQTT%s: (%p): << msg type:0x%02x length:0x%08x Size:00000004.
    [00:02:15.738,311] <dbg> net_mqtt_enc.pack_utf8_str: (0x20020620): >> str_size:00000006 cur:0x200222e9, end:0x200223e4
    [00:02:15.738,311] <dbg> net_mqtt_enc.pack_uint16: (0x20020620): >> val:0004 cur:0x200222e9, end:0x200223e4
    [00:02:15.738,311] <dbg> net_mqtt_enc.connect_request_encode: (0x20020620): Encoding Protocol Version 04.
    [00:02:15.738,342] <dbg> net_mqtt_enc.pack_uint8: (0x20020620): >> val:04 cur:0x200222ef, end:0x200223e4
    [00:02:15.738,342] <dbg> net_mqtt_enc.pack_uint8: (0x20020620): >> val:00 cur:0x200222f0, end:0x200223e4
    [00:02:15.738,342] <dbg> net_mqtt_enc.connect_request_encode: (0x20020620): Encoding Keep Alive Time 003c.
    [00:02:15.738,372] <dbg> net_mqtt_enc.pack_uint16: (0x20020620): >> val:003c cur:0x200222f1, end:0x200223e4
    [00:02:15.738,372] <dbg> net_mqtt_enc.connect_request_encode: (0x20020620): Encoding Client Id. Str:ss-first-test Size:0000000d.
    [00:02:15.738,403] <dbg> net_mqtt_enc.pack_utf8_str: (0x20020620): >> str_size:0000000f cur:0x200222f3, end:0x200223e4
    [00:02:15.738,403] <dbg> net_mqtt_enc.pack_uint16: (0x20020620): >> val:000d cur:0x200222f3, end:0x200223e4
    [00:02:15.738,433] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20020620): << msg type:0x10 length:0x00000019
    [00:02:15.738,433] <dbg> net_mqtt_enc.packet_length_encode: (0x20020620): >> length:0x00000019 cur:0x00000000, end:0x00000000
    [00:02:15.738,433] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20020620): Fixed header length = 02
    [00:02:15.738,464] <dbg> net_mqtt_enc.pack_uint8: (0x20020620): >> val:10 cur:0x200222e7, end:0x200223e4
    [00:02:15.738,464] <dbg> net_mqtt_enc.packet_length_encode: (0x20020620): >> length:0x00000019 cur:0x200222e8, end:0x200223e4
    [00:02:15.739,562] <dbg> net_mqtt.client_connect: (0x20020620): Connect completed
    [00:02:15.739,593] <dbg> ss_aws.aws_iot_test_work: Connect success!
    --- 7 messages dropped ---
    [00:02:16.368,774] <dbg> net_mqtt_dec.unpack_uint8: (0x20020620): << val:00
    [00:02:16.368,774] <dbg> net_mqtt_dec.unpack_uint8: (0x20020620): >> cur:0x200221e7, end:0x200221e8
    --- 3 messages dropped ---
    [00:02:16.368,774] <dbg> net_mqtt_dec.unpack_uint8: (0x20020620): << val:00
    [00:02:16.368,804] <dbg> net_mqtt_dec.connect_ack_decode: (0x20020620): [CID 0x20021ff4]: session_present_flag: 0
    [00:02:16.368,835] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x20020620): [CID 0x20021ff4]: return_code: 0
    [00:02:16.368,865] <dbg> aws_iot.mqtt_evt_handler: MQTT client connected!
    [00:02:16.368,865] <dbg> ss_aws.cloud_evt_handler: CLOUD_EVT_CONNECTED
    [00:02:16.368,865] <dbg> ss_aws.cloud_evt_handler: CLOUD_EVT_READY
    [00:02:16.368,896] <dbg> aws_iot.aws_iot_send: Publishing to topic: ss-test-topic
    [00:02:16.368,896] <dbg> net_mqtt.mqtt_publish: (0x20020620): [CID 0x20021ff4]:[State 0x06]: >> Topic size 0x0000000d, Data size 0x0000001d
    [00:02:16.368,927] <dbg> net_mqtt_enc.pack_utf8_str: (0x20020620): >> str_size:0000000f cur:0x200222e9, end:0x200223e4
    [00:02:16.368,927] <dbg> net_mqtt_enc.pack_uint16: (0x20020620): >> val:000d cur:0x200222e9, end:0x200223e4
    [00:02:16.368,988] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20020620): Fixed header length = 02
    [00:02:16.369,018] <dbg> net_mqtt_enc.pack_uint8: (0x20020620): >> val:32 cur:0x200222e7, end:0x200223e4
    [00:02:16.369,049] <dbg> net_mqtt_enc.packet_length_encode: (0x20020620): >> length:0x0000002e cur:0x200222e8, end:0x200223e4
    [00:02:16.369,079] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport writing 19 bytes.
    [00:02:16.369,873] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport write complete.
    [00:02:16.369,903] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport writing 29 bytes.
    [00:02:16.370,605] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport write complete.
    [00:02:16.370,635] <dbg> net_mqtt.mqtt_publish: (0x20020620): [CID 0x20021ff4]:[State 0x06]: << result 0x00000000
    [00:02:16.370,666] <dbg> ss_aws.cloud_evt_handler: Cloud send success!
    [00:02:17.648,651] <dbg> ss_aws.aws_iot_test_work: Input!
    [00:02:17.648,681] <dbg> net_mqtt.mqtt_input: (0x20020620): state:0x00000006
    [00:02:17.648,712] <dbg> net_mqtt_dec.unpack_uint8: (0x20020620): >> cur:0x200221e4, end:0x200221e6
    [00:02:17.648,712] <dbg> net_mqtt_dec.unpack_uint8: (0x20020620): << val:40
    [00:02:17.648,742] <dbg> net_mqtt_dec.packet_length_decode: (0x20020620): length:0x00000002
    [00:02:17.648,773] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x20020620): [CID 0x20021ff4]: Received MQTT_PKT_TYPE_PUBACK!
    [00:02:17.648,773] <dbg> net_mqtt_dec.unpack_uint16: (0x20020620): >> cur:0x200221e6, end:0x200221e8
    [00:02:17.648,803] <dbg> net_mqtt_dec.unpack_uint16: (0x20020620): << val:2f38
    [00:02:17.648,803] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 12088 result = 0
    [00:02:27.648,925] <dbg> ss_aws.aws_iot_test_work: Timeout!
    [00:02:27.648,956] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport writing 2 bytes.
    [00:02:27.655,731] <dbg> net_mqtt.client_write: (0x20020620): [0x20021ff4]: Transport write complete.
    [00:02:27.655,761] <dbg> net_mqtt_sock_tls.mqtt_client_tls_disconnect: (0x20020620): Closing socket 2
    [00:02:27.656,921] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = 0
    [00:02:27.656,921] <dbg> ss_aws.cloud_evt_handler: CLOUD_EVT_DISCONNECTED
    [00:02:27.656,951] <dbg> ss_aws.aws_iot_test_work: disconnect call success!
    [00:02:27.656,951] <dbg> ss_aws.aws_iot_test_work: We are at the end!
    uart:~$ 
    uart:~$ 
    [00:02:35.130,950] <dbg> ss_aws.aws_iot_test_work: AWS IoT Work!
    [00:02:35.131,469] <dbg> aws_iot.broker_init: IPv4 Address found 54.149.99.172
    [00:02:35.131,805] <dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20020620): Created socket 2   << This is the last thing that is printed, no matter how long you wait
    uart:~$ 
    

  • I think this is a bug associated with the bsdlib version 0.6.1. If you update NCS this should be fixed.

  • That did it!  Any idea when 0.6.2 will get into a numbered nrf release (like 1.2.1)?

Related