Client doesn't reconnect after broker closes connection

[ghiasum]

Hello,

I am using AWS IoT broker and using mqtt-sn-pub from mqtt-sn-tools to publish a message with sleep time and keep alive of 30 seconds.

./mqtt-sn-pub -h ###.###.###.### -t test1/test -m "hello1234" -i client1 -p 10000 -q 1 -e 30 -k 30

After about a minute i see this error message on gateway log

Error: BrokerRecvTask can't receive a packet from the broker errno=0 client1

This seems to be the result of the broker closing the SSL connection due to keep alive timeout. If i use netstat i can see the connection no longer exists.

After this if i try to publish again i keep getting failed to receive PUBACK warning.

./mqtt-sn-pub -h ###.###.###.### -t test1/test -m "hello1234"  -i client1 -p 10000 -q 1 -e 30 -k 30
2019-12-04 19:24:43 WARN  Failed to receive PUBACK after PUBLISH

Looking at the gateway log it seems like the gateway does not forward the connect message to the broker the second time around. Shouldn't the gateway be sending the connect message again once keep alive time is expired?

Also if sleep duration is exceeded without any communication from client what is the behaviour of the gateway in this case?

20191204 192321.213   CONNECT           <---  client1                             0D 04 04 01 00 1E 63 6C 69 65 6E 74 31
     PacketHandleTask gets CONNECT      from the client.
Client Status = Disconnected
20191204 192321.231   CONNECT           ===>  client1                             10 13 00 04 4D 51 54 54 04 02 00 1E 00 07 63 6C 69 65 6E 74 31
20191204 192321.275   CONNACK           <===  client1                             20 02 00 00
     PacketHandleTask gets CONNACK      from the broker.
20191204 192321.275   CONNACK           --->  client1                             03 05 00
sendto 54.90.121.6:43180 length = 3
recved from 54.90.121.6:43180 length = 16

20191204 192321.276   REGISTER    0001  <---  client1                             10 0A 00 00 00 01 74 65 73 74 31 2F 74 65 73 74
     PacketHandleTask gets REGISTER  0001 from the client.
Client Status = Active
20191204 192321.276   REGACK      0001  --->  client1                             07 0B 00 01 00 01 00
sendto 54.90.121.6:43180 length = 7
recved from 54.90.121.6:43180 length = 16

20191204 192321.277   PUBLISH     0002  <---  client1                             10 0C 20 00 01 00 02 68 65 6C 6C 6F 31 32 33 34
     PacketHandleTask gets PUBLISH  0002 from the client.
Client Status = Active
20191204 192321.277   PUBLISH     0002  ===>  client1                             32 17 00 0A 74 65 73 74 31 2F 74 65 73 74 00 02 68 65 6C 6C 6F 31 32 33 34
20191204 192321.282   PUBACK      0002  <===  client1                             40 02 00 02
     PacketHandleTask gets PUBACK  0002 from the broker.
20191204 192321.282   PUBACK      0002  --->  client1                             07 0D 00 01 00 02 00
sendto 54.90.121.6:43180 length = 7
recved from 54.90.121.6:43180 length = 4
20191204 192321.283   DISCONNECT        <---  client1                             04 18 00 1E
     PacketHandleTask gets DISCONNECT      from the client.
Client Status = Asleep
20191204 192321.283   DISCONNECT        --->  client1                             02 18
sendto 54.90.121.6:43180 length = 2
Error: BrokerRecvTask can't receive a packet from the broker errno=0 client1
recved from 54.90.121.6:34458 length = 13

20191204 192413.646   CONNECT           <---  client1                             0D 04 04 01 00 1E 63 6C 69 65 6E 74 31
     PacketHandleTask gets CONNECT      from the client.
Client Status = Active
20191204 192413.646   CONNACK           --->  client1                             03 05 00
sendto 54.90.121.6:34458 length = 3
recved from 54.90.121.6:34458 length = 16

20191204 192413.647   REGISTER    0001  <---  client1                             10 0A 00 00 00 01 74 65 73 74 31 2F 74 65 73 74
     PacketHandleTask gets REGISTER  0001 from the client.
Client Status = Active
20191204 192413.647   REGACK      0001  --->  client1                             07 0B 00 01 00 01 00
sendto 54.90.121.6:34458 length = 7
recved from 54.90.121.6:34458 length = 16

20191204 192413.647   PUBLISH     0002  <---  client1                             10 0C 20 00 01 00 02 68 65 6C 6C 6F 31 32 33 34
     PacketHandleTask gets PUBLISH  0002 from the client.
Client Status = Active
20191204 192413.656   PUBLISH     0002  ===>  client1                             32 17 00 0A 74 65 73 74 31 2F 74 65 73 74 00 02 68 65 6C 6C 6F 31 32 33 34
Error: BrokerRecvTask can't receive a packet from the broker errno=0 client1
     PacketHandleTask gets DISCONNECT      from the broker.
recved from 54.90.121.6:34458 length = 4
20191204 192443.678   DISCONNECT        <---  client1                             04 18 00 1E
     PacketHandleTask gets DISCONNECT      from the client.
Client Status = Asleep
20191204 192443.678   DISCONNECT        --->  client1                             02 18
sendto 54.90.121.6:34458 length = 2

[ty4tw]

Hi ghiasum,

Thank you for your report. It must be a Bug. GW does not disconnect the client in case of it's status is Awake or Sleep when the broker Disconnect it.

Could you change code as follows and try it?

Line 149 In MQTTSNGWBrokerRecvTask.c

    else if (rc == -1)
    {
        WRITELOG("%s BrokerRecvTask can't receive a packet from the broker errno=%d %s%s\n", ERRMSG_HEADER, errno, client->getClientId(), ERRMSG_FOOTER);
    }
    else if ( rc == -2 )
    {
        WRITELOG("%s BrokerRecvTask receive invalid length of packet from the broker.  DISCONNECT  %s %s\n", ERRMSG_HEADER, client->getClientId(),ERRMSG_FOOTER);
    }
    else if ( rc == -3 )
    {
        WRITELOG("%s BrokerRecvTask can't get memories for the packet %s%s\n", ERRMSG_HEADER, client->getClientId(), ERRMSG_FOOTER);
    }

    delete packet;

    if ( (rc == -1 || rc == -2) && client->isActive() )
    {
        /* disconnect the client */
        packet = new MQTTGWPacket();
        packet->setHeader(DISCONNECT);
        ev = new Event();
        ev->setBrokerRecvEvent(client, packet);
        _gateway->getPacketEventQue()->post(ev);
    }

Change line 164

if ( (rc == -1 || rc == -2) && client->isActive() )

to

if ( (rc == -1 || rc == -2) && ( client->isActive()  || client->isSleep() || client->isAwake() ))

Thank you for your cooperation.

[ghiasum]

Hi ty4tw,

I tried your changes but unfortunately results were pretty much the same as before.

20191206 170847.941   CONNECT           <---  client1                             0D 04 04 01 00 0A 63 6C 69 65 6E 74 31
     PacketHandleTask gets CONNECT      from the client.
Client Status = Disconnected
20191206 170847.967   CONNECT           ===>  client1                             10 13 00 04 4D 51 54 54 04 02 00 0A 00 07 63 6C 69 65 6E 74 31
20191206 170848.104   CONNACK           <===  client1                             20 02 00 00
     PacketHandleTask gets CONNACK      from the broker.
20191206 170848.104   CONNACK           --->  client1                             03 05 00
sendto 54.90.121.6:34921 length = 3
recved from 54.90.121.6:34921 length = 16

20191206 170848.105   REGISTER    0001  <---  client1                             10 0A 00 00 00 01 74 65 73 74 31 2F 74 65 73 74
     PacketHandleTask gets REGISTER  0001 from the client.
Client Status = Active
20191206 170848.105   REGACK      0001  --->  client1                             07 0B 00 01 00 01 00
sendto 54.90.121.6:34921 length = 7
recved from 54.90.121.6:34921 length = 16

20191206 170848.106   PUBLISH     0002  <---  client1                             10 0C 20 00 01 00 02 68 65 6C 6C 6F 31 32 33 34
     PacketHandleTask gets PUBLISH  0002 from the client.
Client Status = Active
20191206 170848.106   PUBLISH     0002  ===>  client1                             32 17 00 0A 74 65 73 74 31 2F 74 65 73 74 00 02 68 65 6C 6C 6F 31 32 33 34
20191206 170848.111   PUBACK      0002  <===  client1                             40 02 00 02
     PacketHandleTask gets PUBACK  0002 from the broker.
20191206 170848.111   PUBACK      0002  --->  client1                             07 0D 00 01 00 02 00
sendto 54.90.121.6:34921 length = 7
recved from 54.90.121.6:34921 length = 4
20191206 170848.111   DISCONNECT        <---  client1                             04 18 00 0A
     PacketHandleTask gets DISCONNECT      from the client.
Client Status = Asleep
20191206 170848.112   DISCONNECT        --->  client1                             02 18
sendto 54.90.121.6:34921 length = 2
Error: BrokerRecvTask can't receive a packet from the broker errno=0 client1
     PacketHandleTask gets DISCONNECT      from the broker.
^[[Arecved from 54.90.121.6:54439 length = 13

20191206 170910.799   CONNECT           <---  client1                             0D 04 04 01 00 0A 63 6C 69 65 6E 74 31
     PacketHandleTask gets CONNECT      from the client.
Client Status = Active
20191206 170910.799   CONNACK           --->  client1                             03 05 00
sendto 54.90.121.6:54439 length = 3
recved from 54.90.121.6:54439 length = 16

20191206 170910.799   REGISTER    0001  <---  client1                             10 0A 00 00 00 01 74 65 73 74 31 2F 74 65 73 74
     PacketHandleTask gets REGISTER  0001 from the client.
Client Status = Active
20191206 170910.800   REGACK      0001  --->  client1                             07 0B 00 01 00 01 00
sendto 54.90.121.6:54439 length = 7
recved from 54.90.121.6:54439 length = 16

20191206 170910.800   PUBLISH     0002  <---  client1                             10 0C 20 00 01 00 02 68 65 6C 6C 6F 31 32 33 34
     PacketHandleTask gets PUBLISH  0002 from the client.
Client Status = Active
20191206 170910.811   PUBLISH     0002  ===>  client1                             32 17 00 0A 74 65 73 74 31 2F 74 65 73 74 00 02 68 65 6C 6C 6F 31 32 33 34
Error: BrokerRecvTask can't receive a packet from the broker errno=0 client1
     PacketHandleTask gets DISCONNECT      from the broker.
recved from 54.90.121.6:54439 length = 4
20191206 170920.811   DISCONNECT        <---  client1                             04 18 00 0A
     PacketHandleTask gets DISCONNECT      from the client.
Client Status = Asleep
20191206 170920.811   DISCONNECT        --->  client1                             02 18
sendto 54.90.121.6:54439 length = 2

[ty4tw]

Hi ghiasum,

I forgot to add

    case DISCONNECT:
        client->disconnected();    // Just change Client's status to "Disconnected"
        break;

To Line 362 of MQTTSNGWPacketHandleTask.c as follows:

void PacketHandleTask::transparentPacketHandler(Client*client, MQTTGWPacket* packet)
{
    switch (packet->getType())
    {
    case CONNACK:
        _mqttConnection->handleConnack(client, packet);
        break;
    case PINGRESP:
        _mqttConnection->handlePingresp(client, packet);
        break;
    case PUBLISH:
        _mqttPublish->handlePublish(client, packet);
        break;
    case PUBACK:
        _mqttPublish->handlePuback(client, packet);
        break;
    case PUBREC:
        _mqttPublish->handleAck(client, packet, PUBREC);
        break;
    case PUBREL:
        _mqttPublish->handleAck(client, packet, PUBREL);
        break;
    case PUBCOMP:
        _mqttPublish->handleAck(client, packet, PUBCOMP);
        break;
    case SUBACK:
        _mqttSubscribe->handleSuback(client, packet);
        break;
    case UNSUBACK:
        _mqttSubscribe->handleUnsuback(client, packet);
        break;
    case DISCONNECT:
        client->disconnected();    // Just change Client's status to "Disconnected"
        break;
    default:
        break;
    }
}

[ghiasum]

Ok just got around to trying this and it solved the issue. Thanks for your help!