MQTT_SIMPLE error -128

[flau]

Hi, I am trying the MQTT_SIMPLE sample on both the nRF9160DK and my own custom board.  I have mfw_nrf9160_1.3.1 on both nRF9160 and I am using SDK v1.8.0.  LTE connection seems ok, but I don't seem to be able to connect to my AWS EC2.  Here are the console messages:

*** Booting Zephyr OS build v2.7.0-ncs1 ***
[00:00:00.205,871] <wrn> at_notif: Already initialized. Nothing to do
[00:00:00.205,932] <inf> at_host: UART check failed: 12. Dropping buffer and retrying.
[00:00:00.225,006] <inf> mqtt_simple: The MQTT simple sample started
[00:00:00.225,006] <inf> mqtt_simple: Disabling PSM and eDRX
[00:00:00.225,830] <inf> mqtt_simple: LTE Link Connecting...
[00:00:11.566,528] <inf> mqtt_simple: LTE Link Connected!
[00:00:12.205,474] <inf> mqtt_simple: IPv4 Address found 52.60.???.???
[00:00:12.205,505] <dbg> mqtt_simple.client_id_get: client_id = my-client-id
[00:00:12.205,932] <dbg> net_mqtt_sock_tcp.mqtt_client_tcp_connect: (0x20014ac8): Created socket 1
[00:00:12.588,592] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:00:12.588,592] <inf> mqtt_simple: to topic: testing len: 7
[00:00:12.588,592] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x00]: >> Topic size 0x00000007, Data size 0x00000023
[00:00:12.712,982] <dbg> net_mqtt_enc.connect_request_encode: (0x20014ac8): Encoding Protocol Version 04.
--- 6 messages dropped ---
[00:00:12.712,982] <dbg> net_mqtt_enc.connect_request_encode: (0x20014ac8): Encoding Keep Alive Time 003c.
--- 4 messages dropped ---
[00:00:12.713,043] <dbg> net_mqtt_enc: Encoding Username.
?? ?? ?? ?? ?? ?? ?? |???????
[00:00:12.713,043] <dbg> net_mqtt_enc.pack_utf8_str: (0x20014ac8): >> str_size:00000009 cur:0x200154d3, end:0x20015536
[00:00:12.713,073] <dbg> net_mqtt_enc.pack_uint16: (0x20014ac8): >> val:0007 cur:0x200154d3, end:0x20015536
[00:00:12.713,073] <dbg> net_mqtt_enc: Encoding Password.
?? ?? ?? ?? ?? ?? ?? |???????
[00:00:12.713,073] <dbg> net_mqtt_enc.pack_utf8_str: (0x20014ac8): >> str_size:00000009 cur:0x200154dc, end:0x20015536
[00:00:12.713,104] <dbg> net_mqtt_enc.pack_uint16: (0x20014ac8): >> val:0007 cur:0x200154dc, end:0x20015536
[00:00:12.713,104] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20014ac8): << msg type:0x10 length:0x0000002a
--- 1 messages dropped ---
[00:00:12.713,134] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20014ac8): Fixed header length = 02
[00:00:12.713,165] <dbg> net_mqtt_enc.pack_uint8: (0x20014ac8): >> val:10 cur:0x200154b9, end:0x20015536
[00:00:12.713,165] <dbg> net_mqtt_enc.packet_length_encode: (0x20014ac8): >> length:0x0000002a cur:0x200154ba, end:0x20015536
[00:00:12.713,806] <dbg> net_mqtt.client_connect: (0x20014ac8): Connect completed
[00:00:12.713,836] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:00:12.713,867] <err> mqtt_simple: Publish failed: -128
[00:00:12.734,344] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:00:12.734,344] <inf> mqtt_simple: to topic: testing len: 7
[00:00:12.734,375] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:00:12.734,405] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:00:12.734,436] <err> mqtt_simple: Publish failed: -128
[00:00:12.785,095] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:00:12.785,095] <inf> mqtt_simple: to topic: testing len: 7
[00:00:12.785,095] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:00:12.785,125] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:00:12.785,125] <err> mqtt_simple: Publish failed: -128
[00:00:12.825,714] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:00:12.825,714] <inf> mqtt_simple: to topic: testing len: 7
[00:00:12.825,714] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:00:12.825,744] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:00:12.825,775] <err> mqtt_simple: Publish failed: -128
[00:00:12.936,889] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:00:12.936,889] <inf> mqtt_simple: to topic: testing len: 7
[00:00:12.936,920] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:00:12.936,950] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:00:12.936,950] <err> mqtt_simple: Publish failed: -128
[00:01:12.713,043] <err> mqtt_simple: ERROR: mqtt_live: -128
[00:01:12.713,043] <inf> mqtt_simple: Disconnecting MQTT client...
[00:01:12.713,073] <err> mqtt_simple: Could not disconnect MQTT client: -128
[00:01:12.713,073] <inf> mqtt_simple: Reconnecting in 60 seconds...
[00:01:12.747,802] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:01:12.747,833] <inf> mqtt_simple: to topic: testing len: 7
[00:01:12.747,833] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:01:12.747,863] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:01:12.747,863] <err> mqtt_simple: Publish failed: -128
[00:01:12.778,411] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:01:12.778,411] <inf> mqtt_simple: to topic: testing len: 7
[00:01:12.778,411] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:01:12.778,442] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:01:12.778,442] <err> mqtt_simple: Publish failed: -128
[00:01:12.808,990] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:01:12.808,990] <inf> mqtt_simple: to topic: testing len: 7
[00:01:12.808,990] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:01:12.809,020] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:01:12.809,020] <err> mqtt_simple: Publish failed: -128
[00:01:12.930,297] <inf> mqtt_simple: Publishing: Hello from nRF91 MQTT Simple Sample
[00:01:12.930,297] <inf> mqtt_simple: to topic: testing len: 7
[00:01:12.930,297] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: >> Topic size 0x00000007, Data size 0x00000023
[00:01:12.930,328] <dbg> net_mqtt.mqtt_publish: (0x20014b48): [CID 0x20014bf0]:[State 0x02]: << result 0xffffff80
[00:01:12.930,328] <err> mqtt_simple: Publish failed: -128

I masked the broker IP address, username and password here for the obvious reason.  My understanding is that error 128 means "socket not connected".

Below is my prj.conf.

#
# Copyright (c) 2020 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

# Networking
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=n
CONFIG_NET_SOCKETS_OFFLOAD=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_LOG=y

# LTE link control
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

# Modem library
CONFIG_NRF_MODEM_LIB=y

# AT Host
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_AT_HOST_LIBRARY=y

# MQTT
CONFIG_MQTT_LIB=y
CONFIG_MQTT_LIB_TLS=n
CONFIG_MQTT_CLEAN_SESSION=y
CONFIG_MQTT_LOG_LEVEL_DBG=y

# Application
CONFIG_MQTT_PUB_TOPIC="testing"
CONFIG_MQTT_SUB_TOPIC="testing"
CONFIG_MQTT_CLIENT_ID="my-client-id"
CONFIG_MQTT_BROKER_HOSTNAME="ec2-52-60-???-???.ca-central-1.compute.amazonaws.com"
CONFIG_MQTT_BROKER_PORT=????

# Button support
CONFIG_DK_LIBRARY=y

# Enable logging
CONFIG_LOG=y
CONFIG_MQTT_SIMPLE_LOG_LEVEL_DBG=y

# Memory
CONFIG_MAIN_STACK_SIZE=4096
CONFIG_HEAP_MEM_POOL_SIZE=2048

# NewLib C
CONFIG_NEWLIB_LIBC=y

And here is my Kconfig.

#
# Copyright (c) 2020 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

menu "MQTT simple sample"
config MQTT_PUB_TOPIC
string "MQTT publish topic"
default "testing"

config MQTT_SUB_TOPIC
string "MQTT subscribe topic"
default "testing"

config MQTT_CLIENT_ID
string "MQTT Client ID"
help
Use a custom Client ID string. If not set, the client ID will be
generated based on IMEI number (for nRF9160 based targets) or
randomly (for other platforms).
default "my-client-id"

config MQTT_BROKER_HOSTNAME
string "MQTT broker hostname"
default "ec2-52-60-???-???.ca-central-1.compute.amazonaws.com"

config MQTT_BROKER_PORT
int "MQTT broker port"
default ????

config MQTT_MESSAGE_BUFFER_SIZE
int "MQTT message buffer size"
default 128

config MQTT_PAYLOAD_BUFFER_SIZE
int "MQTT payload buffer size"
default 128

config BUTTON_EVENT_PUBLISH_MSG
string "The message to publish on a button event"
default "Hello from nRF91 MQTT Simple Sample"

config BUTTON_EVENT_BTN_NUM
int "The button number"
default 1

config MQTT_RECONNECT_DELAY_S
int "Seconds to delay before attempting to reconnect to the broker."
default 60

config LTE_CONNECT_RETRY_DELAY_S
int "Seconds to delay before attempting to retry LTE connection."
default 120

config MQTT_TLS_SEC_TAG
int "TLS credentials security tag"
default 24

config MQTT_TLS_SESSION_CACHING
bool "Enable TLS session caching"

config MQTT_TLS_PEER_VERIFY
int "Set peer verification level"
default 2
help
Set to 0 for VERIFY_NONE, 1 for VERIFY_OPTIONAL, and 2 for
VERIFY_REQUIRED.

endmenu

menu "Zephyr Kernel"
source "Kconfig.zephyr"
endmenu

module = MQTT_SIMPLE
module-str = MQTT Simple
source "${ZEPHYR_BASE}/subsys/logging/Kconfig.template.log_config"

Can anyone please help me locate the problem?  Your help is very much appreciated.

[Didrik Rokhaug]

Hi,

First of all, it looks like you are trying to publish messages before you have established an MQTT connection. This makes it a bit harder to read through the log.

However, it looks like the server is not responding to the MQTT Connect request (I am not able to determine if it responds to the TCP SYN packet or not).

Does your broker require a particular client ID (the device is currently using "my-client-id")?

If you use the new Trace Collector v2 Preview application in nRF Connect for Desktop, you should be able to take a modem trace and decode it into a Wireshark .pcap, which will let you see the IP traffic between the device and server. This (and particularly the "live capture" feature) is incredibly usefull when debugging issues like this.

To enable modem tracing on the device, you must set CONFIG_NRF_MODEM_LIB_TRACE_ENABLED=y.

Best regards,

Didrik

[flau]

Thanks Didrik for your quick response.  I checked on the client ID and there doesn't seem to be any particular requirement.  But I changed the client ID to just "testing" now.  I wasn't able to get Trace Collector v2 Preview working.  It stuck at detecting firmware version.  Anyway, I commented out the entire while loop in the mqtt_simple and below is the console messages.

*** Booting Zephyr OS build v2.7.0-ncs1 ***
Connecting to LTE...
[00:00:00.206,085] <wrn> at_notif: Already initialized. Nothing to do
[00:00:00.206,146] <inf> at_host: UART check failed: 12. Dropping buffer and retrying.
Connected to LTE

[00:00:12.630,432] <dbg> net_mqtt_enc.connect_request_encode: (0x20018a80): Encoding Protocol Version 04.
--- 9 messages dropped ---
[00:00:12.630,462] <dbg> net_mqtt_enc.pack_uint8: (0x20018a80): >> val:00 cur:0x2001944e, end:0x200194c2
[00:00:12.630,493] <dbg> net_mqtt_enc.connect_request_encode: (0x20018a80): Encoding Keep Alive Time 003c.
[00:00:12.630,493] <dbg> net_mqtt_enc.pack_uint16: (0x20018a80): >> val:003c cur:0x2001944f, end:0x200194c2
[00:00:12.630,493] <dbg> net_mqtt_enc: Encoding Client Id.

74 65 73 74 69 6e 67 |testing

[00:00:12.630,493] <dbg> net_mqtt_enc.pack_utf8_str: (0x20018a80): >> str_size:00000009 cur:0x20019451, end:0x200194c2
[00:00:12.630,523] <dbg> net_mqtt_enc.pack_uint16: (0x20018a80): >> val:0007 cur:0x20019451, end:0x200194c2
[00:00:12.630,523] <dbg> net_mqtt_enc: Encoding Username.
?? ?? ?? ?? ?? ?? ?? |???????
[00:00:12.630,523] <dbg> net_mqtt_enc.pack_utf8_str: (0x20018a80): >> str_size:00000009 cur:0x2001945a, end:0x200194c2
[00:00:12.630,554] <dbg> net_mqtt_enc.pack_uint16: (0x20018a80): >> val:0007 cur:0x2001945a, end:0x200194c2
[00:00:12.630,554] <dbg> net_mqtt_enc: Encoding Password.
?? ?? ?? ?? ?? ?? ?? |???????
[00:00:12.630,554] <dbg> net_mqtt_enc.pack_utf8_str: (0x20018a80): >> str_size:00000009 cur:0x20019463, end:0x200194c2
[00:00:12.630,584] <dbg> net_mqtt_enc.pack_uint16: (0x20018a80): >> val:0007 cur:0x20019463, end:0x200194c2
[00:00:12.630,615] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20018a80): << msg type:0x10 length:0x00000025
[00:00:12.630,645] <dbg> net_mqtt_enc.packet_length_encode: (0x20018a80): >> length:0x00000025 cur:(nil), end:(nil)
[00:00:12.630,645] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20018a80): Fixed header length = 02
[00:00:12.630,676] <dbg> net_mqtt_enc.pack_uint8: (0x20018a80): >> val:10 cur:0x20019445, end:0x200194c2
[00:00:12.630,706] <dbg> net_mqtt_enc.packet_length_encode: (0x20018a80): >> length:0x00000025 cur:0x20019446, end:0x200194c2
[00:00:12.634,979] <dbg> net_mqtt.client_connect: (0x20018a80): Connect completed

Does the last line mean I am connected?

Thanks again.

[Didrik Rokhaug]

flau said:

I wasn't able to get Trace Collector v2 Preview working.  It stuck at detecting firmware version.

Sounds like the device isnæt outputting any traces.

Did you set CONFIG_NRF_MODEM_LIB_TRACE_ENABLED=y?

You can find a more complete guide on how to enable modem tracing here: https://infocenter.nordicsemi.com/topic/ug_trace_collector/UG/trace_collector/intro.html

It uses the Trace Collector V1, but the process is the same on the device side, so it s still relevant.

You could also try to just capture a raw trace, and see if that works (the trace file should grow in the order of kilobytes per second when connected to a network and not in idle).

flau said:

[00:00:12.634,979] <dbg> net_mqtt.client_connect: (0x20018a80): Connect completed

Does the last line mean I am connected?

It means that you have established a TCP connection. But you still don't have an MQTT connection.

Are you able to connect to your broker with other clients (e.g. a computer desktop client)?

Are you able to get any logs from the broker? Does the logs show that it got a connect request from your device?

[flau]

I believe you can close this ticket now.  I have no problem subscribing and publishing to test.mosquitto.org with authentication.  Seems the problem is my AWS certificate.