Copyright © https://mongoose-os.com

Mongoose OS Forum

frame

ESP8266 MQTT TLS client disconnect

I'm running MQTT TLS client on esp8266. When the broker sends a message, the client seems to receive the MQTT publish successfully (and handle it). However, the MQTT client seems to disconnect (and then proceed to automatically reconnect). While troubleshooting, I notice a comment in "mg_lwip_if_recved()" about "Currently SSL acknowledges data immediately.". Is this related to why my client disconnects from MQTT?

If so, is there a fix? If not, can someone suggest what might be causing the MQTT disconnect? Brief log below:

mg_lwip_tcp_recv_cb 0x3fff1c54 0x3fffaadc 85 0
ssl_socket_recv 5 85 85 85
ssl_socket_recv 80 85 80 85
mg_ssl_if_read 0x3fff1c54 1024 -> 37
mg_lwip_ssl_recv 0x3fff1c54 0x0 SSL_read 1024 = 37
mg_recv_common 0x3fff1c54 37 0
mgos_mqtt_ev MQTT PUBLISH event: 203
call_topic_handler PUBLISH and topic match
mqtt_app_rx_task Mapp: RX:msg=011, attr=0000
mqtt_app_rx_task Mapp: success
mc_send_rc Cloud to Pic: good
mg_lwip_if_recved 0x3fff1c54 0x3fffaadc 37
ssl_socket_recv 5 - nothing to read
mg_ssl_if_read 0x3fff1c54 1024 -> -26880
mg_lwip_ssl_recv 0x3fff1c54 0x0 SSL_read 1024 = -1
mg_lwip_tcp_write_tc 0x3fffaadc tcp_write 53 = 0
mg_ssl_if_write 0x3fff1c54 4 -> 4
mg_lwip_ssl_send 0x3fff1c54 SSL_write 4 = 4, 1073643536

heartbeat_blink_time Tick
mg_lwip_tcp_sent_cb 0x3fff1c54 0x3fffaadc 53

mg_lwip_tcp_recv_cb 0x3fff1c54 0x3fffaadc 53 0
mg_lwip_tcp_recv_cb 0x3fff1c54 0x3fffaadc 0 0
ssl_socket_recv 5 53 53 53
ssl_socket_recv 48 53 48 53
mg_ssl_if_read 0x3fff1c54 1024 -> -30848
mg_lwip_ssl_recv 0x3fff1c54 0x0 SSL_read 1024 = -3
mg_close_conn 0x3fff1c54 2096 1073710388

mg_lwip_tcp_write_tc 0x3fffaadc tcp_write 53 = 0

mg_lwip_if_destroy_c 0x3fff1c54 tcp_close 0x3fffaadc
mgos_mqtt_ev MQTT Disconnect

Comments

  • rojerrojer Dublin, Ireland

    set debug.mbedtls_level to 3 and let's see what mbedtls has to say.

  • I have the same problem.

    Output with debug level 3:

    [Jul  1 11:17:31.967] mqtt_global_reconnec MQTT connecting after 1945 ms
    [Jul  1 11:17:33.917] mqtt_global_connect  MQTT connecting to a1g7tfbctltzn3.iot.eu-west-1.amazonaws.com:8883
    [Jul  1 11:17:35.693] mgos_mqtt_ev         MQTT Connect (1)
    [Jul  1 11:17:35.800] mgos_mqtt_ev         MQTT CONNACK 0
    [Jul  1 11:17:35.806] mgos_mqtt_ev         Subscribing to '$aws/happyornot/summary'
    [Jul  1 11:17:35.814] mgos_mqtt_ev         Subscribing to 'esp32_05925C/rpc'
    [Jul  1 11:17:35.821] mgos_mqtt_ev         Subscribing to 'esp32_05925C/rpc/#'
    [Jul  1 11:17:35.902] mg_ssl_mbed_log      0x3ffb3f50 mbedtls_ssl_handle_message_type() returned -30848 (-0x7880)
    [Jul  1 11:17:35.912] mg_ssl_mbed_log      0x3ffb3f50 mbedtls_ssl_read_record() returned -30848 (-0x7880)
    [Jul  1 11:17:35.925] mgos_mqtt_ev         MQTT Disconnect

    This repeats forever.

    Any clues?

    Thanked by 1grob
  • rojerrojer Dublin, Ireland

    0x7880 is MBEDTLS_ERR_SSL_PEER_CLOSE_NOTIFY, normal shutdown of a TLS connection. this means the connection was otherwise fine, but server shut it down. this usually means MQTT protocol error, the server didn't like something about what we sent.
    and in this case what is this $aws/happyornot/summary subscription? topics starting with $aws are special, and e.g. $aws/things/foo/shadow/bar is the general format for topics used in aws shadow.
    but what is this $aws/foo/summary stuff? where does it come from?

  • I choose the topic name as I am not aware of any general recommendations. I changed the topic name to something different and now it works. Thank you very much.

  • rojerrojer Dublin, Ireland

    oh, good. you're welcome!

  • edited July 2017

    It appears I also am seeing -0x7880. Does this mean the same thing as the previous post (ie normal connection that the server shut down, probably because of a MQTT protocol error). Thanks for the help!

    
    mg_lwip_tcp_recv_cb  0x3fff1efc 0x3fffab54 85 0
    mg_ssl_mbed_log      0x3fff1efc => read
    mg_ssl_mbed_log      0x3fff1efc => read record
    mg_ssl_mbed_log      0x3fff1efc => fetch input
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 13
    ssl_socket_recv      5 85 85 85
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 13
    mg_ssl_mbed_log      0x3fff1efc ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)
    mg_ssl_mbed_log      0x3fff1efc <= fetch input
    mg_ssl_mbed_log      0x3fff1efc input record: msgtype = 23, version = [3:3], msglen = 80
    mg_ssl_mbed_log      0x3fff1efc => fetch input
    mg_ssl_mbed_log      0x3fff1efc in_left: 5, nb_want: 85, in_buf_size: 13
    mg_ssl_mbed_log      0x3fff1efc grow in_buf 13 => 93
    ssl_socket_recv      80 85 80 85
    mg_ssl_mbed_log      0x3fff1efc in_left: 5, nb_want: 85, in_buf_size: 93
    mg_ssl_mbed_log      0x3fff1efc ssl->f_recv(_timeout)() returned 80 (-0xffffffb0)
    mg_ssl_mbed_log      0x3fff1efc <= fetch input
    mg_ssl_mbed_log      0x3fff1efc => decrypt buf
    mg_ssl_mbed_log      0x3fff1efc <= decrypt buf
    mg_ssl_mbed_log      0x3fff1efc <= read record
    mg_ssl_mbed_log      0x3fff1efc <= read
    mg_ssl_if_read       0x3fff1efc 1024 -> 37
    mg_lwip_ssl_recv     0x3fff1efc 0x0 SSL_read 1024 = 37
    mg_recv_common       0x3fff1efc 37 0
    mgos_mqtt_ev         MQTT PUBLISH event: 203
    call_topic_handler   PUBLISH and topic match
    mqtt_app_rx_task     Mapp: RX:msg=011, attr=0000
    mqtt_app_rx_task     Mapp: ENDPOINT_RC2
    mc_send_rc           Cloud to Pic: good
    mg_lwip_if_recved    0x3fff1efc 0x3fffab54 37
    mg_ssl_mbed_log      0x3fff1efc => read
    mg_ssl_mbed_log      0x3fff1efc => read record
    mg_ssl_mbed_log      0x3fff1efc => fetch input
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 93
    mg_ssl_mbed_log      0x3fff1efc shrink in_buf 93 => 13
    ssl_socket_recv      5 - nothing to read
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 13
    mg_ssl_if_read       0x3fff1efc 1024 -> -26880
    mg_lwip_ssl_recv     0x3fff1efc 0x0 SSL_read 1024 = -1
    mg_ssl_mbed_log      0x3fff1efc => write
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 29 => 33
    mg_ssl_mbed_log      0x3fff1efc => write record
    mg_ssl_mbed_log      0x3fff1efc => encrypt buf
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 33 => 53
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 53 => 85
    mg_ssl_mbed_log      0x3fff1efc before encrypt: msglen = 48, including 16 bytes of IV and 8 bytes of padding
    mg_ssl_mbed_log      0x3fff1efc <= encrypt buf
    mg_ssl_mbed_log      0x3fff1efc output record: msgtype = 23, version = [3:3], msglen = 48
    mg_ssl_mbed_log      0x3fff1efc => flush output
    mg_ssl_mbed_log      0x3fff1efc message length: 53, out_left: 53
    mg_lwip_tcp_write_tc 0x3fffab54 tcp_write 53 = 0
    mg_ssl_mbed_log      0x3fff1efc ssl->f_send() returned 53 (-0xffffffcb)
    mg_ssl_mbed_log      0x3fff1efc shrink out_buf 85 => 29
    mg_ssl_mbed_log      0x3fff1efc <= flush output
    mg_ssl_mbed_log      0x3fff1efc <= write record
    mg_ssl_mbed_log      0x3fff1efc <= write
    mg_ssl_if_write      0x3fff1efc 4 -> 4
    mg_lwip_ssl_send     0x3fff1efc SSL_write 4 = 4, 1073643536
    
    mg_lwip_tcp_sent_cb  0x3fff1efc 0x3fffab54 53
    mg_lwip_tcp_recv_cb  0x3fff1efc 0x3fffab54 53 0
    mg_lwip_tcp_recv_cb  0x3fff1efc 0x3fffab54 0 0
    mg_ssl_mbed_log      0x3fff1efc => read
    mg_ssl_mbed_log      0x3fff1efc => read record
    mg_ssl_mbed_log      0x3fff1efc => fetch input
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 13
    ssl_socket_recv      5 53 53 53
    mg_ssl_mbed_log      0x3fff1efc in_left: 0, nb_want: 5, in_buf_size: 13
    mg_ssl_mbed_log      0x3fff1efc ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)
    mg_ssl_mbed_log      0x3fff1efc <= fetch input
    mg_ssl_mbed_log      0x3fff1efc input record: msgtype = 21, version = [3:3], msglen = 48
    mg_ssl_mbed_log      0x3fff1efc => fetch input
    mg_ssl_mbed_log      0x3fff1efc in_left: 5, nb_want: 53, in_buf_size: 13
    mg_ssl_mbed_log      0x3fff1efc grow in_buf 13 => 61
    ssl_socket_recv      48 53 48 53
    mg_ssl_mbed_log      0x3fff1efc in_left: 5, nb_want: 53, in_buf_size: 61
    mg_ssl_mbed_log      0x3fff1efc ssl->f_recv(_timeout)() returned 48 (-0xffffffd0)
    mg_ssl_mbed_log      0x3fff1efc <= fetch input
    mg_ssl_mbed_log      0x3fff1efc => decrypt buf
    mg_ssl_mbed_log      0x3fff1efc <= decrypt buf
    mg_ssl_mbed_log      0x3fff1efc got an alert message, type: [1:0]
    mg_ssl_mbed_log      0x3fff1efc is a close notify message
    mg_ssl_mbed_log      0x3fff1efc mbedtls_ssl_handle_message_type() returned -30848 (-0x7880)
    mg_ssl_mbed_log      0x3fff1efc mbedtls_ssl_read_record() returned -30848 (-0x7880)
    mg_ssl_if_read       0x3fff1efc 1024 -> -30848
    mg_lwip_ssl_recv     0x3fff1efc 0x0 SSL_read 1024 = -3
    mg_close_conn        0x3fff1efc 2096 1073713572
    mg_ssl_mbed_log      0x3fff1efc => write close notify
    mg_ssl_mbed_log      0x3fff1efc => send alert message
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 29 => 31
    mg_ssl_mbed_log      0x3fff1efc => write record
    mg_ssl_mbed_log      0x3fff1efc => encrypt buf
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 31 => 51
    mg_ssl_mbed_log      0x3fff1efc grow out_buf 51 => 83
    mg_ssl_mbed_log      0x3fff1efc before encrypt: msglen = 48, including 16 bytes of IV and 10 bytes of padding
    mg_ssl_mbed_log      0x3fff1efc <= encrypt buf
    mg_ssl_mbed_log      0x3fff1efc output record: msgtype = 21, version = [3:3], msglen = 48
    mg_ssl_mbed_log      0x3fff1efc => flush output
    mg_ssl_mbed_log      0x3fff1efc message length: 53, out_left: 53
    mg_lwip_tcp_write_tc 0x3fffab54 tcp_write 53 = 0
    mg_ssl_mbed_log      0x3fff1efc ssl->f_send() returned 53 (-0xffffffcb)
    mg_ssl_mbed_log      0x3fff1efc shrink out_buf 83 => 29
    mg_ssl_mbed_log      0x3fff1efc <= flush output
    mg_ssl_mbed_log      0x3fff1efc <= write record
    mg_ssl_mbed_log      0x3fff1efc <= send alert message
    mg_ssl_mbed_log      0x3fff1efc <= write close notify
    mg_lwip_if_destroy_c 0x3fff1efc tcp_close 0x3fffab54
    mgos_mqtt_ev         MQTT Disconnect
    mqtt_global_reconnec MQTT connecting after 2075 ms
    mg_ssl_mbed_log      0x3fff1efc => free
    mg_ssl_mbed_log      0x3fff1efc <= free
    mg_lwip_tcp_error_cb 0x0 conn error -12
    heartbeat_blink_time Tock
    heartbeat_blink_time Tick </code>
  • rojerrojer Dublin, Ireland

    yes, that's the same code. it means MQTT server shut down connection, most likely because it didn't like something.
    you can set debug.mg_mgr_hexdump_file=-- (yes, two dashes) to dump unencrypted traffic on the connection.

    Thanked by 1grob
  • In mgos_mqtt_global_subscribe() th->qos is set for 1. However our client is set for qos 0. The broker was disconnecting us for a puback. Is there a different way to set the topic handler qos for the global_subscribe?

Sign In or Register to comment.