search

tuanpmt / esp_mqtt

MQTT client library for ESP8266
http://tuanpm.net/post/esp_mqtt/
MIT License
1.14k stars 400 forks source link

MQTT Disconnect - Connect Endless Loop #131

Closed hannes-angst closed 7 years ago

hannes-angst commented 7 years ago

I ran into a strange problem, using your code on Sonoff devices:

    (1) Wifi connection, 
    (2) mqqt connect, 
    (3) some mqtt sub (see log below) 
    (4) one pub,  (see log below)
    (5) 1-3 secs 

               pm open,type:1 0

    (6) mqtt client implementation disconnects 
    GOTO 2

Logs from esp8266 (sonoff)

    SDK ver: 2.0.0(656edbf) compiled @ Jul 19 2016 17:58:40
    phy ver: 1055, pp ver: 10.2

    mode : softAP(5e:cf:7f:e8:87:a0)
    add if1
    dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
    bcn 100
    [INFO]

    [INFO] BOOTUP...
    [INFO] SDK version:2.0.0(656edbf) rom 0
    [INFO] Time = 114816
    [INFO] Chip ID: 00E887A0
    [INFO] CPU freq: 80 MHz
    [INFO] Program: user1.bin
    [INFO] Flash size map [2]: 1024 KB (512 KB + 512 KB)
    [INFO] Free heap size: 50432
    [INFO] Memory info:
    data  : 0x3ffe8000 ~ 0x3ffe87b4, len: 1972
    rodata: 0x3ffe87c0 ~ 0x3ffe8db4, len: 1524
    bss   : 0x3ffe8db8 ~ 0x3ffef408, len: 26192
    heap  : 0x3ffef408 ~ 0x3fffc000, len: 52216
    [INFO] -------------------------------------------
    [INFO] Remote Switch v.1.3.0
    [INFO] compile time:Dec 18 2016 15:53:56
    [INFO] -------------------------------------------
    [INFO] CONFIG: Load configuration from flash ...
    [INFO] done
    [INFO] Relay OFF
    [DEBUG] MQTT:InitConnection
    [DEBUG] MQTT:InitClient
    bcn 0
    del if1
    usl
    mode : sta(5c:cf:7f:e8:87:a0)
    add if0
    sleep enable,type: 1
    [INFO] Wifi Status: 1
    scandone
    state: 0 -> 2 (b0)
    state: 2 -> 0 (2)
    reconnect
    scandone
    state: 0 -> 2 (b0)
    state: 2 -> 3 (0)
    state: 3 -> 5 (10)
    add 0
    aid 6
    cnt

    connected with olympus, channel 1
    dhcp client start...
    ip:192.168.13.102,mask:255.255.255.0,gw:192.168.13.1
    [INFO] Got WiFi
    [DEBUG] TCP: Connect to ip  192.168.13.100:1883
    [DEBUG] MQTT: Connected to broker 192.168.13.100:1883
    [DEBUG] MQTT: Sending, type: 1, id: 0000
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 4 bytes
    [DEBUG] MQTT: Connected to 192.168.13.100:1883
    [INFO] MQTT: Connected
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/on
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/on", id: 1
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/off
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/off", id: 2
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/name
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/name", id: 3
    [INFO] Subscribe to: /angst/devices/balkon/lampe/ota
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/ota", id: 4
    [INFO] Subscribe to: /angst/devices/discovery/
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/discovery/", id: 5
    [DEBUG] MQTT: queuing publish, length: 220, queue size(215/2048)
    [DEBUG] MQTT: Sending, type: 8, id: 0001
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0002
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0003
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0004
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0005
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 3, id: 0006
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 4 bytes
    [DEBUG] MQTT: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
    pm open,type:1 0
    [DEBUG] TCP: Disconnected callback
    [INFO] MQTT: Disconnected
    [DEBUG] TCP: Free memory
    [DEBUG] TCP: Connect to ip  192.168.13.100:1883
    [DEBUG] TCP: Reconnect to: 192.168.13.100:1883
    [DEBUG] MQTT: Connected to broker 192.168.13.100:1883
    [DEBUG] MQTT: Sending, type: 1, id: 0000
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 4 bytes
    [DEBUG] MQTT: Connected to 192.168.13.100:1883
    [INFO] MQTT: Connected
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/on
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/on", id: 1
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/off
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/off", id: 2
    [INFO] Subscribe to: /angst/devices/balkon/lampe/switch/name
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/switch/name", id: 3
    [INFO] Subscribe to: /angst/devices/balkon/lampe/ota
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/balkon/lampe/ota", id: 4
    [INFO] Subscribe to: /angst/devices/discovery/
    [DEBUG] MQTT: queue subscribe, topic"/angst/devices/discovery/", id: 5
    [DEBUG] MQTT: queuing publish, length: 220, queue size(215/2048)
    [DEBUG] MQTT: Sending, type: 8, id: 0001
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0002
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0003
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0004
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 8, id: 0005
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 5 bytes
    [DEBUG] MQTT: Subscribe successful
    [DEBUG] MQTT: Sending, type: 3, id: 0006
    [DEBUG] TCP: Sent
    [DEBUG] TCP: data received 4 bytes
    [DEBUG] MQTT: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
    [DEBUG] TCP: Disconnected callback
    [INFO] MQTT: Disconnected

Logs from mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100)

    $ tail -F /var/log/mosquitto/mosquitto.log
    1482073390: New client connected from 192.168.13.102 as switch (c1, k120, u'00E887A0').
    1482073405: New connection from 192.168.13.103 on port 1883.
    1482073405: Client switch already connected, closing old connection.
    1482073405: Client switch disconnected.
    1482073411: New client connected from 192.168.13.102 as switch (c1, k120, u'00E887A0').
    1482073425: New connection from 192.168.13.103 on port 1883.
    1482073425: Client switch already connected, closing old connection.
    1482073425: Client switch disconnected.
    1482073431: New client connected from 192.168.13.102 as switch (c1, k120, u'00E887A0').
    1482073446: New connection from 192.168.13.103 on port 1883.

From the mosquitto logs, the session did not time out. Also no timeout-event from MQTT_OnTimeout.

The Wifi-Connection is stable the whole time. 

   $ping -t 192.168.13.102

    Ping wird ausgeführt für 192.168.13.102 mit 32 Bytes Daten:
    Antwort von 192.168.13.102: Bytes=32 Zeit=4ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=1ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=6ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=4ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=1ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=3ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=8ms TTL=128  <---- mqtt disconnect event
    Antwort von 192.168.13.102: Bytes=32 Zeit=2ms TTL=128
    Antwort von 192.168.13.102: Bytes=32 Zeit=5ms TTL=128

MQTT Output

Every entry is one disconnect -> connect cycle.

    $ mosquitto_sub  -v -t /angst/devices/balkon/#
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
        /angst/devices/balkon/lampe/info {"name":"balkon/lampe","app":"Remote Switch","version":"1.3.0","mac":"5c:cf:7f:e8:87:a0","ip":"192.168.13.102","type":"switch","status": "off","base":"/angst/devices/balkon/lampe/"}
tuanpmt commented 7 years ago

This is a problem with qos=1, can you use with qos=0. I will check and resolve this soon. Thanks

hannes-angst commented 7 years ago

Will try this out this evening and posting update.

hannes-angst commented 7 years ago

Thank you very much. This solved the problem. 👍