NRF9160 MQTT Client error -12 (ENOMEM) when Host url is very long

[Jose Cano]

Hello, 

I'm using the mqtt_simple example with the following changes to add WebSockets Secure Support:

# Networking
CONFIG_NET_NATIVE=y

# MQTT
CONFIG_MQTT_LIB_TLS=y
CONFIG_MQTT_LIB_WEBSOCKET=y
CONFIG_WEBSOCKET_CLIENT=y

# Logs
CONFIG_NET_LOG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y

Also I set the Application MQTT topics, clientId, host, port and everything using the CONFIG.

The only change I made in the code was this:

client->transport.type = MQTT_TRANSPORT_SECURE_WEBSOCKET;

The issue is that our Amazon AWS IoT broker url is very long, exactly 1.681 bytes, this is because Amazon give us a url with the token and all the credentials embedded in the url. When I run the code I'm seeing a ENOMEM (-12) when calling the mqtt_connect function.

This is the log:

*** Booting Zephyr OS build v2.4.0-ncs1  ***
The MQTT simple sample started
Provisioning certificates
LTE Link Connecting ...<CR><LF>
+CEREG: 2,"3174","02D71604",7,0,0,"11100000","11100000"
+CSCON: 1
+CEREG: 1,"3174","02D71604",7,,,"11100000","11100000"
LTE Link Connected!
IPv4 Address found 3.211.121.218
ERROR: mqtt_connect -12
[00:00:03.320,220] <ESC><dbg> net_mqtt.client_connect: (0x20020e08): Using transport type 3<ESC>
[00:00:03.320,587] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20020e08): Created socket 1<ESC>[0
[00:00:03.321,044] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_connect: (0x20020e08): mqtt_client_tls_connect: -12<ESC>
[00:00:03.321,075] <ESC><dbg> net_mqtt.mqtt_connect: (0x20020e08): client_connect: -12<ESC>

I was able to debug the error to the following function in mqtt_transport_socket_tls.c

int mqtt_client_tls_connect(struct mqtt_client *client)
{
    .
    .
    .
    
    if (tls_config->hostname) {
		ret = setsockopt(client->transport.tls.sock, SOL_TLS,
				 TLS_HOSTNAME, tls_config->hostname,
				 strlen(tls_config->hostname));
		if (ret < 0) {
			goto error;
		}
	}
	
	.
	.
	.
	
}

So my question is how I can somehow increase the memory that the setsockopt function uses when setting the hostname on the socket.

I already tested increasing the main stack and heap memory using the CONFIG with no luck.

# Memory
CONFIG_MAIN_STACK_SIZE=8192
CONFIG_HEAP_MEM_POOL_SIZE=16384

Btw I'm using NCS v1.4.0 and modem fw 1.2.3.

Any help will be appreciated.

Thanks! 

[Didrik Rokhaug]

Hi,

I don't think there are any ways to increase the max size of an socket option in NCS v1.4.0.

However, in NCS 1.5.0 and newer, we have changed the arcitecture of the bsd library (and renamed it to modem_lib), which allows more control over the sizes of the shared memory buffers between the modem and the application.

It might be that you can get it to work if you increase CONFIG_NRF_MODEM_LIB_HEAP_SIZE (the default is 1024). But, as I said, that requires you to upgrade to NCS v1.5.0 or newer.

Best regards,

Didrik

[Jose Cano]

Hi,

Thanks for the reply. Now the error is gone with the latest NCS 1.6.1 and the CONFIG_NRF_MODEM_LIB_HEAP_SIZE set to a bigger number (2048 in my case).

However, now I'm getting another error -104 (ECONNRESET) when trying to connect to the host.

My broker url is something like this: 

wss://a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com/mqtt?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA5LIR3OD4PNZVUF73%2F20210818%2Fus-east-1%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20210818T160046Z&X-Amz-SignedHeaders=host&X-Amz-Signature=71799e3b5b11041c942f91a08104496728ae010871689c5cbb353b59765f224a&X-Amz-Security-Token=IQoJb3JpZ2luX2VjEGgaCXVzLWVhc3QtMSJHMEUCIQDN734sppYDiuxLqXcqLgdfME8k%2F68eQEs7Ws6xcabfVwIgGoOd5Vr6LUWLtLemX0HSLZN7YrrKFwL7jnf4bh9q%2FVcqmgQIkf%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FARAAGgw5MTc1NDk4Mzg1ODQiDIw8KE5rmwBVO6O%2FEiruA%2FubL8pj9ycCNm2EO8B%2F%2BZuMnQMydHsoGQVfMN6lmHS%2FIkpqopmm6mlwZ1rphA2bhHrRx%2BnSN5v092TrU%2BMT8IN%2FFVaDy3HCDaJeqC3X6u4Cbzyq98kn4sf8vNc2KoO180ryYyXb2z2KwbWckcsXge8Kv7EVW5NU3AwHJ9sD3g2YW0rNe83GWiWOk96j0j26sQjosdUFaIB%2ByTy8rp6%2FxP3la%2FnCCJ59ORUrCOybJX7xpO6hbPJqLeJ3r04hl2Q5NuN1LNzS61c9NS6OrFHqW9adt%2B91MxmpgYQrnFRn9CD72Er1vg1Rb8yAmN%2FRBUyd4Ac5Gi%2Bh%2BCAZa6RclJDI%2B5PRYbWfr6LQK5emy9jCw%2BEYPtxtSb8DGC3fI5A2IBTuqq8HM6XE%2BBrjEea2%2B5PuDrJx4OIe6G8buHnLsbDTs%2FkNPR7IMu0NNFj%2B%2F6roJxjPQZngktj1d6VT1XzWPgLSO5a2bffYCyQVFBmw0WiI4DNSIEVonmZ9oDZHo9OWlt6i8vnxJd1tEw97R2JSK2i%2FWMIero%2F2UJ6ZEmtVA%2BiSkaRd09iVf62cN4Hoq20RIJEHk%2FTp6DCbBaJAZ93pWUSh3xfqgu1iuNsUm76D%2BZyGIsTFNtDJdepULq18o2my91dHNmnxlIyk7H4spkK%2FSI0FMK7d9IgGOoUC0aFuhth7Awb05SsYETk5RBycwcMH6V9bIffIoZYCzai5g3%2Fio%2Ff22INC0OUZR4%2B6QA8PDZJPHu8qVk%2B%2FeIAWsOd%2Fbbty5xg16UmLabps6%2B7U3DHTPlVbbX7qoviD1YCWQ7xdc2CqNSK9PqKGEwI5T7jIzfFjWIc5Tubil1e7GY9g7aLonwKPV12mKpmOzxmt0PSqI1AgVIaxRx6dh0PGHh7MsrB%2ByKrHA4YMM%2B1pggjFg%2Bv4I1AP0GxnLnZLfa5Uoqawap68KBBWznXyy0RmOVKP6gSI9CAM%2FGxff1aFPbNI60PWQvCRJsIQ0n85CHaBR%2B2dzX98CTE6izFRhJJ8Yn7IaOpO

And because of our policy it only works if the cliend_id is set this one (it changes depending on the broker url): 

devices:60de0ce0ed9a344969e7063c:5dea729db307982a01eb5b47:p:h4Y

 

If I set the CONFIG_MQTT_BROKER_HOSTNAME to the full url the getaddrinfo function fails to resolve the host so I had to modify a little bit the code to add the short hostname that will be only a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com. That way the getaddrinfo function resolves the ip address of the host.

Also I enabled Websockets and TLS and changed the MQTT transport type to secure websocket.

client->transport.type = MQTT_TRANSPORT_SECURE_WEBSOCKET;

and inside the TLS config I set the 

tls_cfg->hostname = MQTT_BROKER_HOSTNAME_FULL;

// Where MQTT_BROKER_HOSTNAME_FULL is the full broker url: a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com/mqtt?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA5LIR3OD4PNZVUF73%2F20210818%2Fus-east-1%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20210818T160046Z&X-Amz-SignedHeaders=host&X-Amz-Signature=71799e3...

When I run the application this is the LOG I get:

*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.212,707] <ESC><inf> mqtt_simple: The MQTT simple sample started<ESC>
[00:00:00.220,092] <ESC><inf> mqtt_simple: Provisioning certificates<ESC>
[00:00:00.227,111] <ESC><inf> mqtt_simple: Disabling PSM and eDRX<ESC>
[00:00:00.240,966] <ESC><inf> mqtt_simple: LTE Link Connecting...<ESC>

8/18/2021 08:18:09.703 [RX] - +CEREG: 2,"3174","02D71604",7,0,0,"11100000","11100000"
+CSCON: 1
+CEREG: 1,"3174","02D71604",7,,,"11100000","11100000"
[00:00:02.127,532] <ESC><inf> mqtt_simple: LTE Link Connected!<ESC>
[00:00:02.283,996] <ESC><inf> mqtt_simple: IPv4 Address found 3.212.203.9<ESC>
client_id = devices:60de0ce0ed9a344969e7063c:5dea729db307982a01eb5b47:p:h4Y
[00:00:02.298,828] <ESC><inf> mqtt_simple: TLS enabled<ESC>
[00:00:02.304,473] <ESC><inf> mqtt_simple: Full hostname: a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com/mqtt?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA5LIR3OD4PNZVUF73%2F20210818%2Fus-east-1%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20210818T160046Z&X-Amz-SignedHeaders=host&X-Amz-Signature=71799e3b5b11041c942f91a08104496728ae010871689c5cbb353b59765f224a&X-Amz-Security-Token=IQoJb3JpZ2luX2VjEGgaCXVzLWVhc3QtMSJHMEUCIQDN734sppYDiuxLqXcqLgdfME8k%2F68eQEs7Ws6xcabfVwIgGoOd5Vr6LUWLtLemX0HSLZN7YrrKFwL7jnf4bh9q%2FVcqmgQIkf%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FARAAGgw5MTc1NDk4Mzg1ODQiDIw8KE5rmwBVO6O%2FEiruA%2FubL8pj9ycCNm2EO8B%2F%2BZuMnQMydHsoGQVfMN6lmHS%2FIkpqopmm6mlwZ1rphA2bhHrRx%2BnSN5v092TrU%2BMT8IN%2FFVaDy3HCDaJeqC3X6u4Cbzyq98kn4sf8vNc2KoO180ryYyXb2z2KwbWckcsXge8Kv7EVW5NU3AwHJ9sD3g2YW0rNe83GWiWOk96j0j26sQjosdUFaIB%2ByTy8rp6%2FxP3la%2FnCCJ59ORUrCOybJX7xpO6hbPJqLeJ3r04hl2Q5NuN1LNzS61c9NS6OrFHqW9adt%2B91MxmpgYQrnFRn9CD72Er1vg1Rb8yAmN%2FRBUyd4Ac5Gi%2Bh%2BCAZa6RclJDI%2B5PRYbWfr6LQK5emy9jCw%2BEYPtxtSb8DGC3fI5A2IBTuqq8HM6XE%2BBrjEea2%2B5PuDrJx4OIe6G8buHnLsbDTs%2FkNPR7IMu0NNFj%2B%2F6roJxjPQZngktj1d6VT1XzWPgLSO5a2bffYCyQVFBmw0WiI4DNSIEVonmZ9oDZHo9OWlt6i8vnxJd1tEw97R2JSK2i%2FWMIero%2F2UJ6ZEmtVA%2BiSkaRd09iVf62cN4Hoq20RIJEHk%2FTp6DCbBaJAZ93pWUSh3xfqgu1iuNsUm76D%2BZyGIsTFNtDJdepULq18o2my91dHNmnxlIyk7H4spkK%2FSI0FMK7d9IgGOoUC0aFuhth7Awb05SsYETk5RBycwcMH6V9bIffIoZYCzai5g3%2Fio%2Ff22INC0OUZR4%2B6QA8PDZJPHu8qVk%2B%2FeIAWsOd%2Fbbty5xg16UmLabps6%2B7U3DHTPlVbbX7qoviD1YCWQ7xdc2CqNSK9PqKGEwI5T7jIzfFjWIc5Tubil1e7GY9g7aLonwKPV12mKpmOzxmt0PSqI1AgVIaxRx6dh0PGHh7MsrB%2ByKrHA4YMM%2B1pggjFg%2Bv4I1AP0GxnLnZLfa5Uoqawap68KBBWznXyy0RmOVKP6gSI9CAM%2FGxff1aFPbNI60PWQvCRJsIQ0n85CHaBR%2B2dzX98CTE6izFRhJJ8Yn7IaOpO<ESC>
Connecting to a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com:8883
[00:00:02.477,691] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20015170): Created socket 1<ESC>
[00:00:03.712,066] <ESC><err> mqtt_simple: mqtt_connect -104<ESC>
[00:00:03.720,336] <ESC><inf> mqtt_simple: Reconnecting in 60 seconds...<ESC>

I know that the Broker Url and Client_id works because I'm using MQTTBox client and I can connect to the broker using the same certificate file that I uploaded to the modem.

As you can see in the following image the MQTT Box Mqtt client is connected to the broker using websockets secure.

I'm not sure why Im getting that ECONNRESET error. I traced the error to the following function:

int mqtt_client_tls_connect(struct mqtt_client *client) {
    .
    .
    .
    
    ret = zsock_connect(client->transport.tls.sock, client->broker,
			    peer_addr_size);
	if (ret < 0) {
		goto error;
	}
    
    .
    .
    .
}

The client->broker is set to the result of the getaddrinfo function inside the broker_init() function on main.c.

Can you help me with this issue? 

To summarize:

• I'm trying to connect to a AMZ iot broker that has a long url because of the token being embedded on the url.
• The broker uses Secure Web Sockets
• I'm getting the ECONNRESET when trying to connect to the socket using zsock_connect function.

Thanks in advance.

[Didrik Rokhaug]

The hostname in this case is just a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com. So that is what you should use with getaddrinfo (as you are already doing), and what you should use for hostname verification.

My guess is that the error is because you use the full URL, and not just the hostname for hostname verification.

[Jose Cano]

Hi,

You are right, the hostname in this case should be only the a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com.

When I changed it the device could create the socket and connect to it.

After that, the device sends the WS handshake and I get the "Connect completed" message.

This is the function I'm on:

static int client_connect(struct mqtt_client *client)
{
	int err_code;
	struct buf_ctx packet;

	err_code = mqtt_transport_connect(client);
	if (err_code < 0) {
		return err_code;
	}

	tx_buf_init(client, &packet);
	MQTT_SET_STATE(client, MQTT_STATE_TCP_CONNECTED);

	err_code = connect_request_encode(client, &packet);
	if (err_code < 0) {
		goto error;
	}

	/* Send MQTT identification message to broker. */
	err_code = mqtt_transport_write(client, packet.cur,
					packet.end - packet.cur);
	if (err_code < 0) {
		goto error;
	}

	client->internal.last_activity = mqtt_sys_tick_in_ms_get();

	/* Reset the unanswered ping count for a new connection */
	client->unacked_ping = 0;

	MQTT_TRC("Connect completed");

	return 0;

error:
	client_disconnect(client, err_code, false);
	return err_code;
}

The mqtt_transport_connect function is returning fine (err_code is 0, and I get the "Connect Completed" message).

But now, I'm having another issue on the function mqtt_transport_write when sending the MQTT identification message to the broker, the device just hangs inside that function and never returns.

I debugged the code, and I put a breakpoint inside the function mqtt_transport_write() -> websocket_send_msg() -> websocket_prepare_and_send() the function that never returns is the send_msg().

static int websocket_prepare_and_send(struct websocket_context *ctx,
				      uint8_t *header, size_t header_len,
				      uint8_t *payload, size_t payload_len,
				      int32_t timeout)
{
	struct iovec io_vector[2];
	struct msghdr msg;

	io_vector[0].iov_base = header;
	io_vector[0].iov_len = header_len;
	io_vector[1].iov_base = payload;
	io_vector[1].iov_len = payload_len;

	memset(&msg, 0, sizeof(msg));

	msg.msg_iov = io_vector;
	msg.msg_iovlen = ARRAY_SIZE(io_vector);

	if (HEXDUMP_SENT_PACKETS) {
		LOG_HEXDUMP_DBG(header, header_len, "Header");
		LOG_HEXDUMP_DBG(payload, payload_len, "Payload");
	}

#if defined(CONFIG_NET_TEST)
	/* Simulate a case where the payload is split to two. The unit test
	 * does not set mask bit in this case.
	 */
	return verify_sent_and_received_msg(&msg, !(header[1] & BIT(7)));
#else
	k_timeout_t tout = K_FOREVER;

	if (timeout != SYS_FOREVER_MS) {
		tout = K_MSEC(timeout);
	}

	return sendmsg(ctx->real_sock, &msg,
		       K_TIMEOUT_EQ(tout, K_NO_WAIT) ? MSG_DONTWAIT : 0);
#endif /* CONFIG_NET_TEST */
}

I noticed that the timeout is SYS_FOREVER_MS and it came from the function mqtt_client_websocket_write:

int mqtt_client_websocket_write(struct mqtt_client *client, const uint8_t *data,
				uint32_t datalen)
{
	uint32_t offset = 0U;
	int ret;

	while (offset < datalen) {
		ret = websocket_send_msg(client->transport.websocket.sock,
					 data + offset, datalen - offset,
					 WEBSOCKET_OPCODE_DATA_BINARY,
					 true, true, SYS_FOREVER_MS);
		if (ret < 0) {
			return -errno;
		}

		offset += ret;
	}

	return 0;
}

I have other question:

Where I should add the other part of the broker url after the /mqtt (?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA5LIR3OD4PNZVUF73%2F20210818%2Fus-east-1%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20210818...) because if I add it on the client->transport.websocket.config.url, I got an error when doing the WS handshake.

Btw, this is the log I have:

*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.218,536] <ESC><inf> mqtt_simple: The MQTT simple sample started<ESC>
[00:00:00.225,860] <ESC><inf> mqtt_simple: Provisioning certificates<ESC>
[00:00:00.232,818] <ESC><inf> mqtt_simple: Disabling PSM and eDRX<ESC>
[00:00:00.246,643] <ESC><inf> mqtt_simple: LTE Link Connecting...<ESC>

8/20/2021 08:22:45.075 [RX] - +CEREG: 2,"3174","02D71604",7,0,0,"11100000","11100000"
+CSCON: 1
+CEREG: 1,"3174","02D71604",7,,,"11100000","11100000"
[00:00:02.242,706] <ESC><inf> mqtt_simple: LTE Link Connected!<ESC>
[00:00:02.485,595] <ESC><inf> mqtt_simple: IPv4 Address found 3.218.12.230<ESC>
client_id = devices:60de0ce0ed9a344969e7063c:5dea729db307982a01eb5b47:p:tJH
[00:00:02.500,488] <ESC><inf> mqtt_simple: TLS enabled<ESC>
Connecting to a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com:443
[00:00:02.512,756] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20015170): Created socket 1<ESC>
[00:00:03.937,988] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20015170): Connect completed<ESC>
[00:00:03.948,883] <ESC><dbg> net_http.Data to send
                                  47 45 54 20 2f 6d 71 74  74 20 48 54 54 50 2f 31 |GET /mqt t HTTP/1
                                  2e 31 0d 0a 48 6f 73 74  3a 20 61 32 37 32 74 64 |.1..Host : a272td
                                  79 6d 73 6e 35 6e 37 39  2d 61 74 73 2e 69 6f 74 |ymsn5n79 -ats.iot
                                  2e 75 73 2d 65 61 73 74  2d 31 2e 61 6d 61 7a 6f |.us-east -1.amazo
                                  6e 61 77 73 2e 63 6f 6d  0d 0a 53 65 63 2d 57 65 |naws.com ..Sec-We
                                  62 53 6f 63 6b 65 74 2d  50 72 6f 74 6f 63 6f 6c |bSocket- Protocol
                                  3a 20 6d 71 74 74 0d 0a  53 65 63 2d 57 65 62 53 |: mqtt.. Sec-WebS
                                  6f 63 6b 65 74 2d 4b 65  79 3a 20 64 75 6f 30 42 |ocket-Ke y: duo0B
                                  38 64 47 6a 42 69 44 42  44 6a 39 76 49 58 2f 4f |8dGjBiDB Dj9vIX/O
                                  51 3d 3d 0d 0a 55 70 67  72 61 64 65 3a 20 77 65 |Q==..Upg rade: we
                                  62 73 6f 63 6b 65 74 0d  0a 43 6f 6e 6e 65 63 74 |bsocket. .Connect
                                  69 6f 6e 3a 20 55 70 67  72 61 64 65 0d 0a 53 65 |ion: Upg rade..Se<ESC>
[00:00:04.073,760] <ESC><dbg> net_http.Data to send
                                  63 2d 57 65 62 53 6f 63  6b 65 74 2d 56 65 72 73 |c-WebSoc ket-Vers
                                  69 6f 6e 3a 20 31 33 0d  0a 0d 0a                |ion: 13. ...     <ESC>
[00:00:04.099,548] <ESC><dbg> net_http.http_client_req: (0x20015170): Sent 731 bytes<ESC>
[00:00:04.564,910] <ESC><dbg> net_http.on_message_begin: (0x20015170): -- HTTP GET response (headers) --<ESC>
[00:00:04.575,225] <ESC><dbg> net_http.on_status: (0x20015170): HTTP response status 101 Switching Protocols<ESC>
[00:00:04.586,059] <ESC><dbg> net_http.print_header_field: (0x20015170): [14] content-length<ESC>
[00:00:04.595,336] <ESC><dbg> net_http.print_header_field: (0x20015170): [1] 0<ESC>
[00:00:04.603,271] <ESC><dbg> net_http.print_header_field: (0x20015170): [7] upgrade<ESC>
[00:00:04.611,785] <ESC><dbg> net_http.print_header_field: (0x20015170): [9] websocket<ESC>
[00:00:04.620,483] <ESC><dbg> net_http.print_header_field: (0x20015170): [10] connection<ESC>
[00:00:04.629,364] <ESC><dbg> net_http.print_header_field: (0x20015170): [7] upgrade<ESC>
[00:00:04.637,817] <ESC><dbg> net_http.print_header_field: (0x20015170): [20] sec-websocket-accept<ESC>
[00:00:04.647,705] <ESC><dbg> net_http.print_header_field: (0x20015170): [28] 1KnKUuefVsvww3RJ7D4dvX6XCRc=<ESC>
[00:00:04.658,325] <ESC><dbg> net_http.print_header_field: (0x20015170): [22] sec-websocket-protocol<ESC>
[00:00:04.668,273] <ESC><dbg> net_http.print_header_field: (0x20015170): [4] mqtt<ESC>
[00:00:04.676,422] <ESC><dbg> net_http.on_headers_complete: (0x20015170): Headers complete<ESC>
[00:00:04.685,516] <ESC><dbg> net_http.on_message_complete: (0x20015170): -- HTTP GET response (complete) --<ESC>
[00:00:04.696,258] <ESC><dbg> net_websocket.response_cb: (0x20015170): [0x20014f10] All the data received (178 bytes)<ESC>
[00:00:04.707,855] <ESC><dbg> net_http.http_client_req: (0x20015170): Received 178 bytes<ESC>
[00:00:04.716,705] <ESC><dbg> net_websocket.websocket_connect: (0x20015170): [0x20014f10] WS connection to peer established (fd 2)<ESC>
[00:00:04.729,553] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_connect: (0x20015170): Connect completed<ESC>
[00:00:04.740,844] <ESC><dbg> net_mqtt_enc.Encoding Protocol Description.
                                      4d 51 54 54                                      |MQTT             <ESC>
[00:00:04.758,514] <ESC><dbg> net_mqtt_enc.pack_utf8_str: (0x20015170): >> str_size:00000006 cur:0x2001c124, end:0x2001c91f<ESC>
[00:00:04.770,751] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20015170): >> val:0004 cur:0x2001c124, end:0x2001c91f<ESC>
[00:00:04.781,951] <ESC><dbg> net_mqtt_enc.connect_request_encode: (0x20015170): Encoding Protocol Version 04.<ESC>
[00:00:04.792,877] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20015170): >> val:04 cur:0x2001c12a, end:0x2001c91f<ESC>
[00:00:04.803,802] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20015170): >> val:00 cur:0x2001c12b, end:0x2001c91f<ESC>
[00:00:04.814,727] <ESC><dbg> net_mqtt_enc.connect_request_encode: (0x20015170): Encoding Keep Alive Time 0005.<ESC>
[00:00:04.825,836] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20015170): >> val:0005 cur:0x2001c12c, end:0x2001c91f<ESC>
[00:00:04.836,944] <ESC><dbg> net_mqtt_enc.Encoding Client Id.
                                      64 65 76 69 63 65 73 3a  36 30 64 65 30 63 65 30 |devices: 60de0ce0
                                      65 64 39 61 33 34 34 39  36 39 65 37 30 36 33 63 |ed9a3449 69e7063c
                                      3a 35 64 65 61 37 32 39  64 62 33 30 37 39 38 32 |:5dea729 db307982
                                      61 30 31 65 62 35 62 34  37 3a 70 3a 74 4a 48    |a01eb5b4 7:p:tJH <ESC>
[00:00:04.884,552] <ESC><dbg> net_mqtt_enc.pack_utf8_str: (0x20015170): >> str_size:00000041 cur:0x2001c12e, end:0x2001c91f<ESC>
[00:00:04.896,728] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20015170): >> val:003f cur:0x2001c12e, end:0x2001c91f<ESC>
[00:00:04.907,928] <ESC><dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015170): << msg type:0x10 length:0x0000004b<ESC>
[00:00:04.919,525] <ESC><dbg> net_mqtt_enc.packet_length_encode: (0x20015170): >> length:0x0000004b cur:(nil), end:(nil)<ESC>
[00:00:04.931,396] <ESC><dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015170): Fixed header length = 02<ESC>
[00:00:04.942,016] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20015170): >> val:10 cur:0x2001c122, end:0x2001c91f<ESC>
[00:00:04.952,850] <ESC><dbg> net_mqtt_enc.packet_length_encode: (0x20015170): >> length:0x0000004b cur:0x2001c123, end:0x2001c91f<ESC>
[00:00:04.965,667] <ESC><dbg> net_websocket.websocket_send_msg: (0x20015170): [0x20014f10] Len 77 BIN/1/final<ESC>
[00:00:04.976,806] <ESC><dbg> net_websocket.Header
                                       82 cd 88 5b 21 9a                                |...[!.           <ESC>
[00:00:04.992,370] <ESC><dbg> net_websocket.Payload
                                       98 10 21 9e c5 0a 75 ce  8c 59 21 9f 88 64 45 ff |..!...u. .Y!..dE.
                                       fe 32 42 ff fb 61 17 aa  ec 3e 11 f9 ed 6b 44 fe |.2B..a.. .>...kD.
                                       b1 3a 12 ae bc 62 17 a3  ed 6c 11 ac bb 38 1b af |.:...b.. .l...8..
                                       ec 3e 40 ad ba 62 45 f8  bb 6b 16 a3 b0 69 40 aa |.>@..bE. .k...i@.
                                       b9 3e 43 af ea 6f 16 a0  f8 61 55 d0 c0          |.>C..o.. .aU..   <ESC>

8/20/2021 08:22:58.555 [RX] - +CSCON: 0

Also I made another test, and I changed the timeout to 5000ms

k_timeout_t tout = K_MSEC(5000);

But same result. 

Can you help me with this issue?

Thanks in advance!

[Didrik Rokhaug]

Jose Cano said:

Where I should add the other part of the broker url after the /mqtt (?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA5LIR3OD4PNZVUF73%2F20210818%2Fus-east-1%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20210818...) because if I add it on the client->transport.websocket.config.url, I got an error when doing the WS handshake.

 I would expect it to go in client->transport.websocket.config.url, as you tried. What error did you get?

Also, a modem trace might be helpful to understand what is going on.

We have also released a preview of our next version of the Trace Collector application, which will let you decode traces yourself.

[Jose Cano]

Hi, 

Thanks for the reply. 

I followed your advise and enabled the modem trace adding the CONFIG_NRF_MODEM_LIB_TRACE_ENABLED=y in the project conf and tested two scenarios:

1. websockets.config.url = "/mqtt": This is the log for this scenario:

*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.230,316] <ESC><inf> mqtt_simple: The MQTT simple sample started<ESC>
[00:00:00.237,609] <ESC><inf> mqtt_simple: Provisioning certificates<ESC>
[00:00:00.244,567] <ESC><inf> mqtt_simple: Disabling PSM and eDRX<ESC>
[00:00:00.267,944] <ESC><inf> mqtt_simple: LTE Link Connecting...<ESC>
+CEREG: 2,"3174","02D71604",7,0,0,"11100000","11100000"
+CSCON: 1
+CEREG: 1,"3174","02D71604",7,,,"11100000","11100000"
[00:00:02.495,697] <ESC><inf> mqtt_simple: LTE Link Connected!<ESC>
[00:00:02.648,559] <ESC><inf> mqtt_simple: IPv4 Address found 52.201.174.87<ESC>
client_id = devices:60de0ce0ed9a344969e7063c:5dea729db307982a01eb5b47:p:tBG
[00:00:02.663,421] <ESC><inf> mqtt_simple: TLS enabled<ESC>
Connecting to a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com:443
[00:00:02.676,452] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20019170): Created socket 1<ESC>
[00:00:04.339,385] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20019170): Connect completed<ESC>
[00:00:04.350,158] <ESC><dbg> net_http.Data to send
                                  47 45 54 20 2f 6d 71 74  74 20 48 54 54 50 2f 31 |GET /mqt t HTTP/1
                                  2e 31 0d 0a 48 6f 73 74  3a 20 61 32 37 32 74 64 |.1..Host : a272td
                                  79 6d 73 6e 35 6e 37 39  2d 61 74 73 2e 69 6f 74 |ymsn5n79 -ats.iot
                                  2e 75 73 2d 65 61 73 74  2d 31 2e 61 6d 61 7a 6f |.us-east -1.amazo
                                  6e 61 77 73 2e 63 6f 6d  0d 0a 53 65 63 2d 57 65 |naws.com ..Sec-We
                                  62 53 6f 63 6b 65 74 2d  50 72 6f 74 6f 63 6f 6c |bSocket- Protocol
                                  3a 20 6d 71 74 74 0d 0a  53 65 63 2d 57 65 62 53 |: mqtt.. Sec-WebS
                                  6f 63 6b 65 74 2d 4b 65  79 3a 20 69 74 44 41 4b |ocket-Ke y: itDAK
                                  41 4b 77 4f 4b 51 46 47  54 73 75 71 56 64 70 75 |AKwOKQFG TsuqVdpu
                                  51 3d 3d 0d 0a 55 70 67  72 61 64 65 3a 20 77 65 |Q==..Upg rade: we
                                  62 73 6f 63 6b 65 74 0d  0a 43 6f 6e 6e 65 63 74 |bsocket. .Connect
                                  69 6f 6e 3a 20 55 70 67  72 61 64 65 0d 0a 53 65 |ion: Upg rade..Se<ESC>
[00:00:04.498,809] <ESC><dbg> net_http.Data to send
                                  63 2d 57 65 62 53 6f 63  6b 65 74 2d 56 65 72 73 |c-WebSoc ket-Vers
                                  69 6f 6e 3a 20 31 33 0d  0a 0d 0a                |ion: 13. ...     <ESC>
[00:00:04.527,832] <ESC><dbg> net_http.http_client_req: (0x20019170): Sent 731 bytes<ESC>

8/25/2021 14:26:28.082 [RX] - [00:00:04.906,768] <ESC><dbg> net_http.on_message_begin: (0x20019170): -- HTTP GET response (headers) --<ESC>
[00:00:04.917,053] <ESC><dbg> net_http.on_status: (0x20019170): HTTP response status 101 Switching Protocols<ESC>
[00:00:04.933,624] <ESC><dbg> net_http.print_header_field: (0x20019170): [14] content-length<ESC>
[00:00:04.943,786] <ESC><dbg> net_http.print_header_field: (0x20019170): [1] 0<ESC>
[00:00:04.954,833] <ESC><dbg> net_http.print_header_field: (0x20019170): [7] upgrade<ESC>
[00:00:04.963,287] <ESC><dbg> net_http.print_header_field: (0x20019170): [9] websocket<ESC>
[00:00:04.972,442] <ESC><dbg> net_http.print_header_field: (0x20019170): [10] connection<ESC>
[00:00:04.983,642] <ESC><dbg> net_http.print_header_field: (0x20019170): [7] upgrade<ESC>
[00:00:04.992,126] <ESC><dbg> net_http.print_header_field: (0x20019170): [20] sec-websocket-accept<ESC>
[00:00:05.001,922] <ESC><dbg> net_http.print_header_field: (0x20019170): [28] 7CVQV+gtLILHNN0r7KzuEkfJdYo=<ESC>
[00:00:05.012,969] <ESC><dbg> net_http.print_header_field: (0x20019170): [22] sec-websocket-protocol<ESC>
[00:00:05.023,834] <ESC><dbg> net_http.print_header_field: (0x20019170): [4] mqtt<ESC>
[00:00:05.035,156] <ESC><dbg> net_http.on_headers_complete: (0x20019170): Headers complete<ESC>
[00:00:05.044,189] <ESC><dbg> net_http.on_message_complete: (0x20019170): -- HTTP GET response (complete) --<ESC>
[00:00:05.055,389] <ESC><dbg> net_websocket.response_cb: (0x20019170): [0x20018f10] All the data received (178 bytes)<ESC>
[00:00:05.066,955] <ESC><dbg> net_http.http_client_req: (0x20019170): Received 178 bytes<ESC>
[00:00:05.075,836] <ESC><dbg> net_websocket.websocket_connect: (0x20019170): [0x20018f10] WS connection to peer established (fd 2)<ESC>
[00:00:05.089,080] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_connect: (0x20019170): Connect completed<ESC>
[00:00:05.101,165] <ESC><dbg> net_mqtt_enc.Encoding Protocol Description.
                                      4d 51 54 54                                      |MQTT             <ESC>
[00:00:05.121,582] <ESC><dbg> net_mqtt_enc.pack_utf8_str: (0x20019170): >> str_size:00000006 cur:0x20020148, end:0x20020943<ESC>
[00:00:05.134,307] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20019170): >> val:0004 cur:0x20020148, end:0x20020943<ESC>
[00:00:05.145,477] <ESC><dbg> net_mqtt_enc.connect_request_encode: (0x20019170): Encoding Protocol Version 04.<ESC>
[00:00:05.156,341] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20019170): >> val:04 cur:0x2002014e, end:0x20020943<ESC>
[00:00:05.167,663] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20019170): >> val:00 cur:0x2002014f, end:0x20020943<ESC>
[00:00:05.182,189] <ESC><dbg> net_mqtt_enc.connect_request_encode: (0x20019170): Encoding Keep Alive Time 0005.<ESC>
[00:00:05.197,692] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20019170): >> val:0005 cur:0x20020150, end:0x20020943<ESC>
[00:00:05.209,289] <ESC><dbg> net_mqtt_enc.Encoding Client Id.
                                      64 65 76 69 63 65 73 3a  36 30 64 65 30 63 65 30 |devices: 60de0ce0
                                      65 64 39 61 33 34 34 39  36 39 65 37 30 36 33 63 |ed9a3449 69e7063c
                                      3a 35 64 65 61 37 32 39  64 62 33 30 37 39 38 32 |:5dea729 db307982
                                      61 30 31 65 62 35 62 34  37 3a 70 3a 74 42 47    |a01eb5b4 7:p:tBG <ESC>
[00:00:05.265,930] <ESC><dbg> net_mqtt_enc.pack_utf8_str: (0x20019170): >> str_size:00000041 cur:0x20020152, end:0x20020943<ESC>
[00:00:05.287,078] <ESC><dbg> net_mqtt_enc.pack_uint16: (0x20019170): >> val:003f cur:0x20020152, end:0x20020943<ESC>
[00:00:05.298,461] <ESC><dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20019170): << msg type:0x10 length:0x0000004b<ESC>
[00:00:05.310,058] <ESC><dbg> net_mqtt_enc.packet_length_encode: (0x20019170): >> length:0x0000004b cur:(nil), end:(nil)<ESC>
[00:00:05.322,723] <ESC><dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20019170): Fixed header length = 02<ESC>
[00:00:05.338,562] <ESC><dbg> net_mqtt_enc.pack_uint8: (0x20019170): >> val:10 cur:0x20020146, end:0x20020943<ESC>
[00:00:05.352,996] <ESC><dbg> net_mqtt_enc.packet_length_encode: (0x20019170): >> length:0x0000004b cur:0x20020147, end:0x20020943<ESC>
[00:00:05.366,516] <ESC><dbg> net_websocket.websocket_send_msg: (0x20019170): [0x20018f10] Len 77 BIN/1/final<ESC>
[00:00:05.380,218] <ESC><dbg> net_websocket.Header
                                       82 cd 14 49 b5 4a                                |...I.J           <ESC>
[00:00:05.395,568] <ESC><dbg> net_websocket.Payload
                                       04 02 b5 4e 59 18 e1 1e  10 4b b5 4f 14 76 d1 2f |...NY... .K.O.v./
                                       62 20 d6 2f 67 73 83 7a  70 2c 85 29 71 79 d0 2e |b ./gs.z p,.)qy..
                                       2d 28 86 7e 20 70 83 73  71 7e 85 7c 27 2a 8f 7f |-(.~ p.s q~.|'*..
                                       70 2c d4 7d 26 70 d1 28  27 79 82 73 2c 7b d4 7a |p,.}&p.( 'y.s,{.z
                                       25 2c d7 7f 76 7d 82 70  64 73 c1 08 53          |%,..v}.p ds..S   <ESC>
[00:00:05.462,341] <ESC><dbg> net_mqtt.client_connect: (0x20019170): Connect completed<ESC>
[00:00:05.470,886] <ESC><dbg> mqtt_simple.main: mqtt_connect: done!<ESC>
[00:00:05.477,661] <ESC><dbg> mqtt_simple.main: fds_init: done!<ESC>
[00:00:05.486,419] <ESC><dbg> mqtt_simple.main: Connection done, starting polling...<ESC>
[00:00:05.621,429] <ESC><dbg> net_mqtt.mqtt_input: (0x20019170): state:0x00000002<ESC>
[00:00:05.629,547] <ESC><dbg> net_websocket.Header
                                       88 00                                            |..               <ESC>
[00:00:05.647,613] <ESC><dbg> net_websocket.websocket_recv_msg: (0x20019170): [0x20018f10] masked 0 mask 0x0000 hdr 2 msg 0<ESC>
[00:00:05.664,367] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_read: (0x20019170): ret: -11, message_type: 9<ESC>
[00:00:05.681,732] <ESC><dbg> net_mqtt_rx.mqtt_read_message_chunk: (0x20019170): [CID 0x20019298]: Transport read error: -11<ESC>
[00:00:07.627,838] <ESC><dbg> net_mqtt.mqtt_input: (0x20019170): state:0x00000002<ESC>
[00:00:07.635,925] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_read: (0x20019170): ret: 0, message_type: 0<ESC>
[00:00:07.651,702] <ESC><dbg> net_mqtt_rx.mqtt_read_message_chunk: (0x20019170): [CID 0x20019298]: Connection closed.<ESC>
[00:00:07.665,771] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_disconnect: (0x20019170): Closing socket 2<ESC>
[00:00:07.683,380] <ESC><dbg> net_websocket.websocket_interal_disconnect: (0x20019170): [0x20018f10] Disconnecting<ESC>
[00:00:07.695,281] <ESC><inf> mqtt_simple: MQTT client disconnected: -128<ESC>
[00:00:07.705,078] <ESC><err> mqtt_simple: mqtt_input: -128<ESC>
[00:00:07.711,486] <ESC><inf> mqtt_simple: Disconnecting MQTT client...<ESC>
[00:00:07.718,902] <ESC><err> mqtt_simple: Could not disconnect MQTT client: -128<ESC>
[00:00:07.731,811] <ESC><inf> mqtt_simple: Reconnecting in 15 seconds...<ESC>

As you can see after the device connects to the mqtt broker I get a Transport read error: -11 inside the mqtt_live function when reading a message chunk.

These are the two trace files for this scenario:

raw_modem_trace_scenario_1

pcap_modem_trace_scenario_1

2. websockets.config.url = "/mqtt?X-Amz-Algorithm=AWS4...". This is the log for this scenario:

*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.230,194] <ESC><inf> mqtt_simple: The MQTT simple sample started<ESC>
[00:00:00.237,518] <ESC><inf> mqtt_simple: Provisioning certificates<ESC>
[00:00:00.244,445] <ESC><inf> mqtt_simple: Disabling PSM and eDRX<ESC>
[00:00:00.267,852] <ESC><inf> mqtt_simple: LTE Link Connecting...<ESC>
+CEREG: 2,"3174","02D71604",7,0,0,"11100000","11100000"
+CSCON: 1
+CEREG: 1,"3174","02D71604",7,,,"11100000","11100000"
[00:00:02.173,492] <ESC><inf> mqtt_simple: LTE Link Connected!<ESC>
[00:00:02.343,292] <ESC><inf> mqtt_simple: IPv4 Address found 3.217.26.2<ESC>
client_id = devices:60de0ce0ed9a344969e7063c:5dea729db307982a01eb5b47:p:tBG
[00:00:02.358,306] <ESC><inf> mqtt_simple: TLS enabled<ESC>
Connecting to a272tdymsn5n79-ats.iot.us-east-1.amazonaws.com:443
[00:00:02.373,382] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20019170): Created socket 1<ESC>
[00:00:04.009,033] <ESC><dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x20019170): Connect completed<ESC>
[00:00:04.019,989] <ESC><dbg> net_http.Data to send
                                  47 45 54 20 2f 6d 71 74  74 3f 58 2d 41 6d 7a 2d |GET /mqt t?X-Amz-
                                  41 6c 67 6f 72 69 74 68  6d 3d 41 57 53 34 2d 48 |Algorith m=AWS4-H
                                  4d 41 43 2d 53 48 41 32  35 36 26 58 2d 41 6d 7a |MAC-SHA2 56&X-Amz
                                  2d 43 72 65 64 65 6e 74  69 61 6c 3d 41 53 49 41 |-Credent ial=ASIA
                                  35 4c 49 52 33 4f 44 34  47 4e 32 46 57 49 50 51 |5LIR3OD4 GN2FWIPQ
                                  25 32 46 32 30 32 31 30  38 32 35 25 32 46 75 73 |%2F20210 825%2Fus
                                  2d 65 61 73 74 2d 31 25  32 46 69 6f 74 64 65 76 |-east-1% 2Fiotdev
                                  69 63 65 67 61 74 65 77  61 79 25 32 46 61 77 73 |icegatew ay%2Faws
                                  34 5f 72 65 71 75 65 73  74 26 58 2d 41 6d 7a 2d |4_reques t&X-Amz-
                                  44 61 74 65 3d 32 30 32  31 30 38 32 35 54 31 35 |Date=202 10825T15
                                  31 36 32 39 5a 26 58 2d  41 6d 7a 2d 53 69 67 6e |1629Z&X- Amz-Sign
                                  65 64 48 65 61 64 65 72  73 3d 68 6f 73 74 26 58 |edHeader s=host&X<ESC>
[00:00:04.165,222] <ESC><dbg> net_http.Data to send
                                  2d 41 6d 7a 2d 53 69 67  6e 61 74 75 72 65 3d 30 |-Amz-Sig nature=0
                                  63 35 37 64 66 37 64 66  64 64 64 36 35 65 61 64 |c57df7df ddd65ead
                                  31 36 34 33 32 39 63 65  66 63 31 37 62 64 36 30 |164329ce fc17bd60
                                  64 30 34 63 38 36 62 35  30 33 35 35 66 32 35 64 |d04c86b5 0355f25d
                                  61 65 32 66 62 38 66 33  62 63 65 39 65 37 36 26 |ae2fb8f3 bce9e76&
                                  58 2d 41 6d 7a 2d 53 65  63 75 72 69 74 79 2d 54 |X-Amz-Se curity-T
                                  6f 6b 65 6e 3d 49 51 6f  4a 62 33 4a 70 5a 32 6c |oken=IQo Jb3JpZ2l
                                  75 58 32 56 6a 45 42 41  61 43 58 56 7a 4c 57 56 |uX2VjEBA aCXVzLWV
                                  68 63 33 51 74 4d 53 4a  48 4d 45 55 43 49 51 43 |hc3QtMSJ HMEUCIQC
                                  75 6e 4a 4e 4e 67 6c 4d  31 55 37 4b 47 53 51 69 |unJNNglM 1U7KGSQi
                                  35 56 78 69 66 30 43 77  46 62 77 51 54 49 33 4e |5Vxif0Cw FbwQTI3N
                                  36 25 32 42 38 50 32 46  36 34 37 4f 41 49 67 64 |6%2B8P2F 647OAIgd<ESC>
[00:00:04.316,680] <ESC><dbg> net_http.Data to send
                                  73 57 49 62 42 32 44 58  4e 52 74 6c 7a 73 41 71 |sWIbB2DX NRtlzsAq
                                  70 73 49 53 25 32 46 67  69 78 6b 58 54 6d 30 53 |psIS%2Fg ixkXTm0S
                                  62 77 65 39 55 62 4f 6c  6e 74 4b 63 71 6b 51 51 |bwe9UbOl ntKcqkQQ
                                  49 53 42 41 41 47 67 77  35 4d 54 63 31 4e 44 6b |ISBAAGgw 5MTc1NDk
                                  34 4d 7a 67 31 4f 44 51  69 44 4a 61 55 4e 48 66 |4Mzg1ODQ iDJaUNHf
                                  37 4f 6a 79 6c 76 44 25  32 46 65 74 79 72 75 41 |7OjylvD% 2FetyruA
                                  32 4b 79 43 43 6c 38 72  7a 65 50 72 43 65 35 4d |2KyCCl8r zePrCe5M
                                  62 51 76 48 49 76 51 48  4a 56 71 4e 39 46 51 30 |bQvHIvQH JVqN9FQ0
                                  41 48 5a 4e 58 33 79 38  55 5a 33 73 4d 45 62 64 |AHZNX3y8 UZ3sMEbd
                                  77 72 43 74 4e 77 74 78  44 70 74 56 4b 4f 78 6e |wrCtNwtx DptVKOxn
                                  58 79 65 74 70 36 39 75  37 4d 4f 6a 6c 43 74 5a |Xyetp69u 7MOjlCtZ
                                  6d 77 25 32 46 76 7a 73  63 4d 57 71 52 6b 25 32 |mw%2Fvzs cMWqRk%2<ESC>
[00:00:04.468,200] <ESC><dbg> net_http.Data to send
                                  46 79 52 78 39 76 76 64  64 25 32 42 42 70 78 30 |FyRx9vvd d%2BBpx0
                                  74 71 4a 33 56 25 32 46  51 35 35 59 6d 75 66 34 |tqJ3V%2F Q55Ymuf4
                                  45 30 54 76 6d 67 41 6e  76 25 32 46 44 59 6a 35 |E0TvmgAn v%2FDYj5
                                  48 45 47 6d 4d 31 66 7a  4e 78 50 61 54 50 35 62 |HEGmM1fz NxPaTP5b
                                  35 35 4a 77 69 56 53 53  61 34 6b 62 74 6d 25 32 |55JwiVSS a4kbtm%2
                                  42 4c 4d 61 50 4b 68 31  41 49 6c 42 5a 46 39 71 |BLMaPKh1 AIlBZF9q
                                  6e 36 4e 74 6c 76 7a 59  75 54 77 63 50 6b 70 71 |n6NtlvzY uTwcPkpq
                                  42 4f 6d 77 49 47 30 51  51 41 72 74 5a 31 62 7a |BOmwIG0Q QArtZ1bz
                                  42 67 25 32 42 38 67 6c  5a 68 78 6a 47 49 53 35 |Bg%2B8gl ZhxjGIS5
                                  73 4b 77 63 50 53 70 36  65 33 35 34 64 5a 69 25 |sKwcPSp6 e354dZi%
                                  32 42 55 25 32 42 64 77  42 53 5a 50 74 6d 58 48 |2BU%2Bdw BSZPtmXH
                                  43 4a 79 76 61 38 57 6f  49 58 69 36 6c 38 4a 56 |CJyva8Wo IXi6l8JV<ESC>
[00:00:04.615,966] <ESC><dbg> net_http.Data to send
                                  5a 70 4d 43 47 49 43 67  50 46 68 78 34 42 72 4f |ZpMCGICg PFhx4BrO
                                  4a 52 7a 4b 6e 4d 76 34  77 76 6a 4d 35 44 33 46 |JRzKnMv4 wvjM5D3F
                                  4f 68 74 73 76 65 4d 6f  51 49 77 44 48 75 63 53 |OhtsveMo QIwDHucS
                                  25 32 42 42 56 75 74 25  32 46 56 72 73 75 48 32 |%2BBVut% 2FVrsuH2
                                  42 4d 76 25 32 46 52 71  65 73 30 6e 6e 51 54 59 |BMv%2FRq es0nnQTY
                                  4a 39 71 38 34 77 62 78  4f 46 48 36 41 42 25 32 |J9q84wbx OFH6AB%2
                                  42 5a 56 4f 68 43 66 4e  76 42 32 75 25 32 46 30 |BZVOhCfN vB2u%2F0
                                  52 6e 77 41 50 39 77 34  25 32 46 4e 42 62 30 73 |RnwAP9w4 %2FNBb0s
                                  66 63 57 38 34 58 52 47  74 44 49 4f 61 61 48 41 |fcW84XRG tDIOaaHA
                                  49 46 50 75 50 31 53 62  51 71 43 59 41 55 52 71 |IFPuP1Sb QqCYAURq
                                  30 54 53 52 4d 72 52 6a  63 6b 37 55 4b 39 62 25 |0TSRMrRj ck7UK9b%
                                  32 46 57 63 71 25 32 46  46 77 38 25 32 42 63 30 |2FWcq%2F Fw8%2Bc0<ESC>
[00:00:04.777,160] <ESC><dbg> net_http.Data to send
                                  4a 75 37 39 58 52 32 5a  68 6d 7a 79 25 32 46 6e |Ju79XR2Z hmzy%2Fn
                                  49 61 75 52 5a 6d 76 39  73 77 62 25 32 42 31 61 |IauRZmv9 sw
8/25/2021 14:33:18.460 [RX] - b%2B1a
                                  59 7a 56 58 25 32 42 6b  4c 45 57 48 6a 64 32 62 |YzVX%2Bk LEWHjd2b
                                  30 5a 6c 32 44 44 49 42  55 39 72 35 53 43 41 70 |0Zl2DDIB U9r5SCAp
                                  4d 76 73 6c 54 72 70 52  56 39 6b 36 30 66 72 78 |MvslTrpR V9k60frx
                                  42 50 74 7a 78 31 67 25  32 42 59 69 41 75 34 73 |BPtzx1g% 2BYiAu4s
                                  43 61 69 6e 38 30 45 61  54 79 44 39 74 5a 6b 25 |Cain80Ea TyD9tZk%
                                  32 42 39 30 4b 70 33 31  6d 4c 25 32 42 56 6d 42 |2B90Kp31 mL%2BVmB
                                  43 25 32 42 57 62 4c 4e  31 6f 37 53 31 36 63 52 |C%2BWbLN 1o7S16cR
                                  57 7a 54 6f 53 73 56 74  7a 36 30 48 61 76 6b 46 |WzToSsVt z60HavkF
                                  6c 57 78 38 33 44 4a 41  32 31 59 41 61 4f 53 63 |lWx83DJA 21YAaOSc
                                  74 7a 25 32 46 6d 73 39  38 62 71 64 65 31 67 61 |tz%2Fms9 8bqde1ga<ESC>
[00:00:04.930,114] <ESC><dbg> net_http.Data to send
                                  25 32 42 67 59 4d 7a 39  6f 65 57 6f 56 56 65 55 |%2BgYMz9 oeWoVVeU
                                  70 6a 65 73 6e 37 31 7a  47 63 25 32 46 4c 32 70 |pjesn71z Gc%2FL2p
                                  4e 6f 36 69 6d 31 38 25  32 46 55 52 7a 4d 4d 32 |No6im18% 2FURzMM2
                                  39 6d 59 6b 47 4f 6f 55  43 25 32 42 55 70 62 61 |9mYkGOoU C%2BUpba
                                  79 39 65 53 6d 52 25 32  42 65 65 45 55 79 5a 64 |y9eSmR%2 BeeEUyZd
                                  51 51 73 76 66 31 35 61  6a 78 49 49 38 53 42 53 |QQsvf15a jxII8SBS
                                  44 43 63 32 47 30 4a 59  54 37 6a 6a 54 65 62 71 |DCc2G0JY T7jjTebq
                                  36 42 4c 65 55 66 63 4d  36 61 56 4f 4f 70 49 64 |6BLeUfcM 6aVOOpId
                                  4a 51 5a 78 73 39 42 4d  44 30 74 37 77 79 50 36 |JQZxs9BM D0t7wyP6
                                  4c 64 77 52 33 39 6e 72  52 44 46 71 6a 6b 63 33 |LdwR39nr RDFqjkc3
                                  59 43 36 4f 6c 72 25 32  42 4d 76 6a 51 5a 6d 31 |YC6Olr%2 BMvjQZm1
                                  64 77 53 59 79 73 77 25  32 46 47 74 6b 30 5a 64 |dwSYysw% 2FGtk0Zd<ESC>
[00:00:05.108,917] <ESC><dbg> net_http.Data to send
                                  64 4b 44 49 4d 25 32 46  77 53 6c 78 75 4b 61 71 |dKDIM%2F wSlxuKaq
                                  70 48 30 46 45 73 48 77  46 73 5a 6f 69 72 25 32 |pH0FEsHw FsZoir%2
                                  46 36 56 53 42 45 6b 6b  44 71 4c 47 72 74 70 4c |F6VSBEkk DqLGrtpL
                                  49 70 5a 4f 78 6b 55 76  4f 51 6f 71 6d 48 66 73 |IpZOxkUv OQoqmHfs
                                  32 43 47 73 71 52 61 34  43 6d 53 4d 72 36 71 6c |2CGsqRa4 CmSMr6ql
                                  7a 41 76 76 55 65 76 76  6c 6a 6e 6a 4e 47 45 7a |zAvvUevv ljnjNGEz
                                  25 32 42 62 6a 32 51 38  4b 37 46 46 6b 61 70 62 |%2Bbj2Q8 K7FFkapb
                                  53 74 79 53 71 4c 49 33  43 41 57 37 64 49 49 58 |StySqLI3 CAW7dIIX
                                  47 61 39 70 43 77 59 65  37 72 64 69 51 30 69 42 |Ga9pCwYe 7rdiQ0iB
                                  6b 56 47 75 39 6d 46 7a  4a 39 77 35 71 59 67 57 |kVGu9mFz J9w5qYgW
                                  65 42 36 41 4f 59 63 64  78 6a 25 32 46 4d 47 7a |eB6AOYcd xj%2FMGz
                                  47 6d 53 4b 74 65 57 6a  69 6b 62 33 35 4c 41 38 |GmSKteWj ikb35LA8<ESC>
[00:00:05.272,644] <ESC><dbg> net_http.Data to send
                                  71 69 76 69 6c 25 32 42  7a 54 50 58 63 51 6b 5a |qivil%2B zTPXcQkZ
                                  46 77 5a 6f 63 51 56 66  34 64 49 44 32 37 37 77 |FwZocQVf 4dID277w
                                  70 4f 4d 70 78 4c 67 20  48 54 54 50 2f 31 2e 31 |pOMpxLg  HTTP/1.1
                                  0d 0a 48 6f 73 74 3a 20  61 32 37 32 74 64 79 6d |..Host:  a272tdym
                                  73 6e 35 6e 37 39 2d 61  74 73 2e 69 6f 74 2e 75 |sn5n79-a ts.iot.u
                                  73 2d 65 61 73 74 2d 31  2e 61 6d 61 7a 6f 6e 61 |s-east-1 .amazona
                                  77 73 2e 63 6f 6d 0d 0a  53 65 63 2d 57 65 62 53 |ws.com.. Sec-WebS
                                  6f 63 6b 65 74 2d 50 72  6f 74 6f 63 6f 6c 3a 20 |ocket-Pr otocol: 
                                  6d 71 74 74 0d 0a 53 65  63 2d 57 65 62 53 6f 63 |mqtt..Se c-WebSoc
                                  6b 65 74 2d 4b 65 79 3a  20 61 42 49 79 32 33 64 |ket-Key:  aBIy23d
                                  62 6a 32 32 61 6d 50 6e  37 32 5a 4b 5a 47 51 3d |bj22amPn 72ZKZGQ=
                                  3d 0d 0a 55 70 67 72 61  64 65 3a 20 77 65 62 73 |=..Upgra de: webs<ESC>
[00:00:05.432,800] <ESC><dbg> net_http.Data to send
                                  6f 63 6b 65 74 0d 0a 43  6f 6e 6e 65 63 74 69 6f |ocket..C onnectio
                                  6e 3a 20 55 70 67 72 61  64 65 0d 0a 53 65 63 2d |n: Upgra de..Sec-
                                  57 65 62 53 6f 63 6b 65  74 2d 56 65 72 73 69 6f |WebSocke t-Versio
                                  6e 3a 20 31 33 0d 0a 0d  0a                      |n: 13... .       <ESC>
[00:00:05.489,532] <ESC><dbg> net_http.http_client_req: (0x20019170): Sent 557 bytes<ESC>
[00:00:05.721,557] <ESC><dbg> net_http.on_message_begin: (0x20019170): -- HTTP GET response (headers) --<ESC>
[00:00:05.733,276] <ESC><dbg> net_http.on_status: (0x20019170): HTTP response status 403 Forbidden<ESC>
[00:00:05.749,053] <ESC><dbg> net_http.print_header_field: (0x20019170): [12] content-type<ESC>
[00:00:05.758,209] <ESC><dbg> net_http.print_header_field: (0x20019170): [16] application/json<ESC>
[00:00:05.768,676] <ESC><dbg> net_http.print_header_field: (0x20019170): [14] content-length<ESC>
[00:00:05.778,015] <ESC><dbg> net_http.print_header_field: (0x20019170): [2] 72<ESC>
[00:00:05.786,132] <ESC><dbg> net_http.print_header_field: (0x20019170): [4] date<ESC>
[00:00:05.794,403] <ESC><dbg> net_http.print_header_field: (0x20019170): [29] Wed, 25 Aug 2021 21:33:19 GMT<ESC>
[00:00:05.805,603] <ESC><dbg> net_http.print_header_field: (0x20019170): [16] x-amzn-RequestId<ESC>
[00:00:05.818,786] <ESC><dbg> net_http.print_header_field: (0x20019170): [36] 5bb6487c-e038-9722-0c2f-e589d92e6da4<ESC>
[00:00:05.832,336] <ESC><dbg> net_http.print_header_field: (0x20019170): [10] connection<ESC>
[00:00:05.841,613] <ESC><dbg> net_http.print_header_field: (0x20019170): [10] keep-alive<ESC>
[00:00:05.850,952] <ESC><dbg> net_http.print_header_field: (0x20019170): [16] x-amzn-ErrorType<ESC>
[00:00:05.860,351] <ESC><dbg> net_http.print_header_field: (0x20019170): [19] ForbiddenException:<ESC>
[00:00:05.869,934] <ESC><dbg> net_http.on_headers_complete: (0x20019170): Headers complete<ESC>
[00:00:05.878,906] <ESC><dbg> net_http.on_body: (0x20019170): Processed 72 length 72<ESC>
[00:00:05.887,908] <ESC><dbg> net_http.on_body: (0x20019170): Calling callback for partitioned 306 len data<ESC>
[00:00:05.899,932] <ESC><dbg> net_websocket.response_cb: (0x20019170): [0x20018f10] Partial data received (306 bytes)<ESC>
[00:00:05.913,696] <ESC><dbg> net_http.on_message_complete: (0x20019170): -- HTTP GET response (complete) --<ESC>
[00:00:05.924,896] <ESC><dbg> net_websocket.response_cb: (0x20019170): [0x20018f10] All the data received (0 bytes)<ESC>
[00:00:05.936,279] <ESC><dbg> net_http.http_client_req: (0x20019170): Received 306 bytes<ESC>
[00:00:05.945,098] <ESC><dbg> net_websocket.websocket_connect: (0x20019170): [0x20018f10] WS handshake failed (1/0)<ESC>
[00:00:05.956,512] <ESC><dbg> net_mqtt_websocket.mqtt_client_websocket_connect: (0x20019170): Websocket connect failed (-113)<ESC>
[00:00:05.976,898] <ESC><err> mqtt_simple: mqtt_connect -113<ESC>
ECONNABORTED (-113)
[00:00:05.987,457] <ESC><inf> mqtt_simple: Reconnecting in 15 seconds...<ESC>

As you can see, I got a handshake failed while trying to connect to the broker.

These are the two trace files for this scenario:

raw_modem_trace_scenario_2

pcap_modem_trace_scenario_2

Maybe with those traces you can know a little more on what is happening when connecting on both scenarios.

Thanks!

[Didrik Rokhaug]

In the first .pcap, it is the server that is closing the connection. Though I am not able to tell why from the logs. My guess is the missing URL parameters.

In the second log, you receive a 403 Forbidden error from the server. There should be more information about why you received the error in the body of the response, but as it is not printed, it is hard to say what is worng.

Is the URL still valid (it has not expired)? Is the signature correct?

Also, out of curiosity, why do you want to use websockets instead of "pure" MQTT, and how do you generate the URL?