[BUG] Can not connect to AWS IoT Core when using Last Will

[tobiasdierich]

Describe the bug When setting a last will on the mqtt client using setWill, the client can not connect to AWS IoT core. Maybe this is related to #52. When trying to connect, the client returns a disconnection due to reason 7. My guess is that when using setWill, the EMC_WAIT_FOR_CONNACK is ignored and it tries to immediately publish a message which causes AWS to close the connection. If I do not set a last will, connecting and publishing to AWS works fine.

Platform: ESP32 TLS: Yes IDE: Arduino IDE for testing Version: 1.4.5

Expected behaviour Can connect to AWS IoT Core MQTT with last will set.

To Reproduce Steps to reproduce the behaviour:

Example code

#include <WiFi.h>
#include <Ticker.h>
#include <espMqttClient.h>

#define WIFI_SSID "WIFI"
#define WIFI_PASSWORD "PASS"

const char* awsEndpoint = "URL";
#define MQTT_PORT 8883

const char certificate_pem_crt[] = "foo";
const char private_pem_key[] = "foo";
const char rootCA[] = "foo";

espMqttClientSecure mqttClient;
Ticker reconnectTimer;

void connectToWiFi() {
  Serial.println("Connecting to Wi-Fi...");
  WiFi.begin(WIFI_SSID, WIFI_PASSWORD);
}

void connectToMqtt() {
  Serial.println("Connecting to MQTT...");
  mqttClient.connect();
}

void WiFiEvent(WiFiEvent_t event) {
  Serial.printf("[WiFi-event] event: %d\n", event);
  switch(event) {
    case SYSTEM_EVENT_STA_GOT_IP:
      Serial.println("WiFi connected");
      Serial.println("IP address: ");
      Serial.println(WiFi.localIP());
      connectToMqtt();
      break;
    case SYSTEM_EVENT_STA_DISCONNECTED:
      Serial.println("WiFi lost connection");
      reconnectTimer.once(5, connectToWiFi);
      break;
    default:
      break;
  }
}

void onMqttConnect(bool sessionPresent) {
  Serial.println("Connected to MQTT.");
  Serial.print("Session present: ");
  Serial.println(sessionPresent);

  uint16_t packetIdSub0 = mqttClient.subscribe("foo/bar/1", 0);
  Serial.print("Subscribing at QoS 0, packetId: ");
  Serial.println(packetIdSub0);

  uint16_t packetIdPub0 = mqttClient.publish("foo/bar/0", 0, false, "test");
  Serial.println("Publishing at QoS 0, packetId: ");
  Serial.println(packetIdPub0);
}

void onMqttDisconnect(espMqttClientTypes::DisconnectReason reason) {
  Serial.printf("Disconnected from MQTT: %u.\n", static_cast<uint8_t>(reason));

  if (WiFi.isConnected()) {
    reconnectTimer.once(5, connectToMqtt);
  }
}

void onMqttSubscribe(uint16_t packetId, const espMqttClientTypes::SubscribeReturncode* codes, size_t len) {
  Serial.println("Subscribe acknowledged.");
  Serial.print("  packetId: ");
  Serial.println(packetId);
  for (size_t i = 0; i < len; ++i) {
    Serial.print("  qos: ");
    Serial.println(static_cast<uint8_t>(codes[i]));
  }
}

void onMqttUnsubscribe(uint16_t packetId) {
  Serial.println("Unsubscribe acknowledged.");
  Serial.print("  packetId: ");
  Serial.println(packetId);
}

void onMqttMessage(const espMqttClientTypes::MessageProperties& properties, const char* topic, const uint8_t* payload, size_t len, size_t index, size_t total) {
  Serial.println("Publish received.");
  Serial.print("  topic: ");
  Serial.println(topic);
  Serial.print("  qos: ");
  Serial.println(properties.qos);
  Serial.print("  dup: ");
  Serial.println(properties.dup);
  Serial.print("  retain: ");
  Serial.println(properties.retain);
  Serial.print("  len: ");
  Serial.println(len);
  Serial.print("  index: ");
  Serial.println(index);
  Serial.print("  total: ");
  Serial.println(total);
}

void onMqttPublish(uint16_t packetId) {
  Serial.println("Publish acknowledged.");
  Serial.print("  packetId: ");
  Serial.println(packetId);
}

void setup() {
  Serial.begin(115200);
  Serial.println();
  Serial.println();

  WiFi.onEvent(WiFiEvent);

  //mqttClient.setInsecure();
  mqttClient.setCACert(rootCA);
  mqttClient.setServer(awsEndpoint, MQTT_PORT);
  mqttClient.setCertificate(certificate_pem_crt);
  mqttClient.setPrivateKey(private_pem_key);
  mqttClient.setClientId("opendtu");
  mqttClient.setWill("foo/bar/will", 2, false, "last");
  mqttClient.setCleanSession(true);
  mqttClient.onConnect(onMqttConnect);
  mqttClient.onDisconnect(onMqttDisconnect);
  mqttClient.onSubscribe(onMqttSubscribe);
  mqttClient.onUnsubscribe(onMqttUnsubscribe);
  mqttClient.onMessage(onMqttMessage);
  mqttClient.onPublish(onMqttPublish);

  connectToWiFi();
}

void loop() {
  delay(1000);
  static uint32_t lastMillis = 0;
  if (millis() - lastMillis > 5000) {
    lastMillis = millis();
    Serial.printf("heap: %u\n", ESP.getFreeHeap());
  }

  mqttClient.publish("foo/bar/0", 0, false, "test");

}

Output:

Disconnected from MQTT: 7.
heap: 211220
Connecting to MQTT...
Disconnected from MQTT: 7.
heap: 211308
Connecting to MQTT...
Disconnected from MQTT: 7.

[bertmelis]

Could you try again but enable debug logging?

The will message is incoporated into the CONNECT message so this might me malformed somehow (or not formed according AWS standards).

Do you know how to enable debug output?

[tobiasdierich]

This is the debug output when it fails to connect:

[     5][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz

Connecting to Wi-Fi...
[    51][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 0 - WIFI_READY
[WiFi-event] event: 0
[   148][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 2 - STA_START
[WiFi-event] event: 2
E (3557) wifi:Association refused temporarily, comeback time 1024 mSec
[  3697][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[  3697][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 203 - ASSOC_FAIL
[  3700][D][WiFiGeneric.cpp:1077] _eventCallback(): WiFi Reconnect Running
[WiFi-event] event: 5
WiFi lost connection
heap: 216568
[  6134][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[  6134][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 201 - NO_AP_FOUND
[  6138][D][WiFiGeneric.cpp:1081] _eventCallback(): WiFi AutoReconnect Running
[WiFi-event] event: 5
WiFi lost connection
[  7659][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 4 - STA_CONNECTED
[WiFi-event] event: 4
[  7678][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 7 - STA_GOT_IP
[  7678][D][WiFiGeneric.cpp:1098] _eventCallback(): STA IP: 192.168.178.29, MASK: 255.255.255.0, GW: 192.168.178.1
[WiFi-event] event: 7
WiFi connected
IP address: 
192.168.178.29
Connecting to MQTT...
[  9096][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[  9096][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.
heap: 214912
Connecting to MQTT...
heap: 157096
[ 15243][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 15243][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.
Connecting to MQTT...
heap: 157388
[ 21345][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 21346][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.

[bertmelis]

That looks like the same debug log as the other issue.

Would it help if you do

if (mqttClient.connected()) {
  mqttClient.publish("foo/bar/0", 0, false, "test");
}

Just to rule out (or confirm) bugs with the wait_for_connack logic.

[tobiasdierich]

I still get the same debug output:

[     5][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz

Connecting to Wi-Fi...
[    50][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 0 - WIFI_READY
[WiFi-event] event: 0
[   148][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 2 - STA_START
[WiFi-event] event: 2
E (3479) wifi:Association refused temporarily, comeback time 1024 mSec
[  3658][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[  3658][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 203 - ASSOC_FAIL
[  3661][D][WiFiGeneric.cpp:1077] _eventCallback(): WiFi Reconnect Running
[WiFi-event] event: 5
WiFi lost connection
heap: 216856
[  6095][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 5 - STA_DISCONNECTED
[  6095][W][WiFiGeneric.cpp:1057] _eventCallback(): Reason: 201 - NO_AP_FOUND
[  6098][D][WiFiGeneric.cpp:1081] _eventCallback(): WiFi AutoReconnect Running
[WiFi-event] event: 5
WiFi lost connection
[  7631][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 4 - STA_CONNECTED
[WiFi-event] event: 4
[  7652][D][WiFiGeneric.cpp:1035] _eventCallback(): Arduino Event: 7 - STA_GOT_IP
[  7652][D][WiFiGeneric.cpp:1098] _eventCallback(): STA IP: 192.168.178.29, MASK: 255.255.255.0, GW: 192.168.178.1
[WiFi-event] event: 7
WiFi connected
IP address: 
192.168.178.29
Connecting to MQTT...
[  9004][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[  9005][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.
heap: 214900
Connecting to MQTT...
[ 15144][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 15145][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.
heap: 214684
Connecting to MQTT...
heap: 157384
[ 21269][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 21270][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.
Connecting to MQTT...
heap: 155832
[ 27404][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 27405][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Disconnected from MQTT: 7.

Commenting out the setWill call I get:

[WiFi-event] event: 7
WiFi connected
IP address: 
192.168.178.29
Connecting to MQTT...
heap: 157208
[ 40460][D][ssl_client.cpp:282] start_ssl_client(): Protocol is TLSv1.2 Ciphersuite is TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256
[ 40461][D][ssl_client.cpp:284] start_ssl_client(): Record expansion is 29
Connected to MQTT.
Session present: 0
Subscribing at QoS 0, packetId: 7
Publishing at QoS 0, packetId: 
1
Subscribe acknowledged.
  packetId: 7
  qos: 0
Publishing message
Publishing message
Publishing message
Publishing message
Publishing message
heap: 169364
Publishing message
Publishing message
Publishing message
Publishing message
Publishing message

[bertmelis]

The thing with the will is that the library only stores pointers to the topic and payload. But in your case, the data should be long lived.

I'm going to dig in the AWS manuals again. See here: https://docs.aws.amazon.com/iot/latest/developerguide/mqtt.html#mqtt-lwt and here: https://docs.aws.amazon.com/iot/latest/developerguide/connect-policy.html Do you need to enable persistent connections?

[tobiasdierich]

For testing purposes I used a "allow all" policy for IoT Core:

{
  "Version": "2012-10-17",
  "Statement": [
    {
      "Effect": "Allow",
      "Action": "*",
      "Resource": "*"
    }
  ]
}

So afaik persistent connections should already be allowed. Is there any way I can help debugging this?

[bertmelis]

Error code 7 isn't helping. AWS is just closing the TCP connection. It would be helpful is you somehow could find in the AWS logs why it does this.

[tobiasdierich]

🤦 I just figured it out. AWS does not support QoS 2 and I set the will to exactly that (see https://docs.aws.amazon.com/iot/latest/developerguide/mqtt.html#mqtt-differences). Changing the QoS to 0 or 1 fixes the issue.

Thanks so much for helping me debug this!

[bertmelis]

Good to hear. And thanks!