TLS Encrypted alert received after MQTT KEEPALIVE sent

[johnhmacleod]

Basic Infos

TLS Encrypted alert received after MQTT KEEPALIVE sent
(Also posted in the PubSubClient repo)

Hardware

Hardware: ESP-12e
Core Version: ?2.1.0-rc2?

Description

Problem description
Sometimes I get a TLS Encrypted alert received after MQTT KEEPALIVE being sent.

I use the WifiSecure object successfully with my PubSubClient MQTT app. However occasionally I get a TLS Encrypted Alert which arrives in the MQTT data stream & breaks the connection to the broker. It only happens in response to a KEEPALIVE being sent (variable, but roughly every 10-20 PINGREQs) and never happens with regular MQTT data traffic and happens with both brokers (Bluemix & Mosquitto) that I have tried.

Settings in IDE

Module: Wemos D1 & Mini
Flash Size: 4MB
CPU Frequency: 80Mhz
Upload Using: SERIAL

[johnhmacleod]

Turned on TLS debug & saw the following...

Typical sequence is (I've reduced the KEEPALIVE time to 5 seconds, publishing every second):
Sent PINGREQ
Received PINGRESP
Publish ok
Publish ok
Publish ok
Publish ok
Sent PINGREQ
Received PINGRESP
Publish ok
Publish ok
Publish ok
Sent PINGREQ
Publish ok
Publish ok
Alert: close notify
(Reconnection follows here)

Now & then I see the following:
Alert: bad record mac
Error: SSL error 20
Alert: unexpected message
Alert: close notify

[johnhmacleod]

A bit more insight. It turns out that the TLS Alert is sent as a result of something else happening. It's a "close notify" alert.

Here's the Wireshark trace during one of these problems.

For the Application Data packets -

• 218 size packets are MQTT publish packets
• 170 size packets are PUBREQ (keepalive requests) packets to the broker.
• 195 size packets are PUBACK (keepalive responses) from the broker.

The long pause from packet 271378 to packet 276514 happens because junk MQTT data arrives. It is 15 seconds because the MQTT library routine getpacket is looking for a packet containing (random amounts) of data which doesn't arrive in the 15 second MQTT timeout period.
Then the (276514)TLS alert (close notify) is generated.

So the questions really are - why are we getting junk data arriving? Why does it only happen when TLS is on? Why is it triggered by the MQTT keepalives?

[igrr]

This seems to be same/related issue as #3002. It looks like the sequence of events is like this:

• some data arrives on the TCP connection
• it is placed into TLS fragment buffer and decrypted
• application layer is notified that some data has arrived
• application layer reads part of the data (one MQTT message?)
• application layer decides to send something
• data is stored into TLS fragment buffer and encrypted (overwriting some/all of the data which was previously received)
• data is sent
• application reads more data from TLS fragment buffer, but that data has now been overwritten by the sent fragment

There is a proposed PR (#3019) which works around this problem.

[johnhmacleod]

That does sound like a possibility. The only incoming data in my code are the KEEPALIVE responses. Would #3002 happen in that scenario?

[igrr]

The fix for this has been implemented in #4024. Please try the latest git version.

[devyte]

Closing this due to lack of feedback and bearssl integration.