Problem with MQTT binding, Doesnt seam to register UNSUBACK?

[daniel....@gmail.com]

Hello

Messages are at my custom MQTT broker (Listens for openhab connection)

First unsubscribe no problems here:

TCP->Read: a20c000f000830332f30312f3032

TCP->Send: b002000f

After updating items for a second time: 

TCP->Read: a20c002a000830332f30312f3032

TCP->Send: b002002a

TCP->Read: a20c002b000830332f30312f3032

TCP->Send: b002002b

MQTT on openhab sends unsubscribe twice? I dont get it..

And If I repeat a new update of any of the configuration:

TCP->Read: a20c004c000830332f30312f3032

TCP->Send: b002004c

TCP->Read: a20c004d000830332f30312f3032

TCP->Send: b002004d

TCP->Read: a20c004e000830332f30312f3032

TCP->Send: b002004e

And so on.. After a couple of days running this can be a very long list and It is just not right...

The Subscribe has no problems, It only sends once every time and get replied:

TCP->Read: 820d005a000830332f30312f303200

TCP->Send: 9003005a00

Have me misunderstood the protocol or am I hunting a bug inside MQTT binding?

http://public.dhe.ibm.com/software/dw/webservices/ws-mqtt/mqtt-v3r1.html#unsuback

Let me know if you need more info

Switch sw1 "sw 1"  {mqtt=">[mysensor:03/01/02:command:ON:1],>[mysensor:03/01/02:command:OFF:0],<[mysensor:03/01/02:command:MAP(1.map)]"}

Thanks!

[daniel....@gmail.com]

The problem exists in latest nightly also.

[Davy Vanherbergen]

Hi,

The MQTT binding will do an unsubscribe/subscribe every time the item configuration is updated. If openHAB sends multiple 'item updated' events, there will be multiple unsubscribe events.

Can you change the log level for the MQTT bundles to trace and post the output here?

Davy

[daniel....@gmail.com]

Hello

At first start there are no problems at all:

10:48:37.512 DEBUG o.o.b.m.internal.MqttActivator[:34] - MQTT binding has been started.

10:48:37.527 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Temp_vind' : 1 subscribers, 0 publishers

10:48:37.527 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '05/10/00'

10:48:37.658 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Hum_vind' : 1 subscribers, 0 publishers

10:48:37.659 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '05/11/01'

10:48:37.807 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Batt_vind' : 1 subscribers, 0 publishers

10:48:37.808 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '05/01/24'

10:48:37.958 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Temp_base' : 1 subscribers, 0 publishers

10:48:37.958 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/10/00'

10:48:38.108 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Hum_base' : 1 subscribers, 0 publishers

10:48:38.108 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/11/01'

10:48:38.258 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Watt1_base' : 1 subscribers, 0 publishers

10:48:38.259 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/01/17'

10:48:38.409 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'KWH1_base' : 1 subscribers, 0 publishers

10:48:38.409 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/03/17'

10:48:38.559 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Watt2_base' : 1 subscribers, 0 publishers

10:48:38.559 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/02/17'

10:48:38.710 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'KWH2_base' : 1 subscribers, 0 publishers

10:48:38.710 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/04/17'

10:48:38.860 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Temp_test' : 1 subscribers, 0 publishers

10:48:38.860 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/10/00'

10:48:39.010 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'Hum_test' : 1 subscribers, 0 publishers

10:48:39.011 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '06/11/01'

10:48:39.162 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'sw1' : 1 subscribers, 2 publishers

10:48:39.162 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '03/01/02'

10:48:39.312 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'sw2' : 1 subscribers, 2 publishers

10:48:39.312 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '03/02/02'

10:48:39.461 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'sw3' : 1 subscribers, 2 publishers

10:48:39.462 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '03/03/02'

10:48:39.612 DEBUG o.o.b.m.i.MqttItemConfig[:71] - Loaded MQTT config for item 'sw4' : 1 subscribers, 2 publishers

10:48:39.612 DEBUG o.o.i.t.m.i.MqttBrokerConnection[:472] - Starting message consumer for broker 'mysensor' on topic '03/04/02'

10:48:39.766 DEBUG o.o.b.m.i.MqttEventBusBinding[:61] - MQTT: Activating event bus binding.

But after updating items a couple of times; see attached log.

[daniel....@gmail.com]

Including the logfile again, Somehow it got in a wierd order; sorry!

Here is the correct one!

[Davy Vanherbergen]

Thanks, I'll investigate and keep you posted.

[daniel....@gmail.com]

In case it's needed here it the items configuration:

Group all

Group a

Group vind      "Vinden"        (all)

Group base      "Källaren"     (all)

Group test      "test"          (all)

Group sw                (all)

Group temperature       (all)

Group humidity          (all)

Group dewpoint          (all)

Group ahumidity         (all)

Group battery           (all)

Number Temp_vind "Temperatur (vinden) [%.1f °C]"                        <temperature>                   (vind,temperature,a)    {mqtt="<[mysensor:05/10/00:state:default]"}

Number Hum_vind "Relativ luftfuktighet (vinden) [%.1f %%]"              <humidity>                      (vind,humidity,a)       {mqtt="<[mysensor:05/11/01:state:default]"}

Number Ahum_vind "Absolut luftfuktighet (vinden) [%.1f g/m³]"                                           (vind,ahumidity,a)

Number Dew_vind "Daggpunkt (vinden) [%.1f °C]"                                                          (vind,dewpoint,a)

Number Batt_vind "Volt batteri (vinden) [%.2f V]"                       <battery>                       (vind,battery,a)        {mqtt="<[mysensor:05/01/24:state:default]"}

Number Temp_base "Temperatur (källaren) [%.1f °C]"                      <temperature>                   (base,temperature,a)    {mqtt="<[mysensor:06/10/00:state:default]"}

Number Hum_base "Relativ luftfuktighet (källaren) [%.1f %%]"            <humidity>                      (base,humidity,a)       {mqtt="<[mysensor:06/11/01:state:default]"}

Number Ahum_base "Absolut luftfuktighet (källaren) [%.1f g/m³]"                                         (base,ahumidity,a)

Number Dew_base "Daggpunkt (källaren) [%.1f °C]"                                                        (base,dewpoint,a)

Number Watt1_base "Huset momentant effekt (källaren) [%.2f W]"          <battery>                       (base,watt,a)           {mqtt="<[mysensor:06/01/17:state:default]"}

Number KWH1_base "Huset total KWh (källaren) [%.2f KWh]"                <battery>                       (base,kwh,a)            {mqtt="<[mysensor:06/03/17:state:default]"}

Number Watt2_base "VP momentant effekt (källaren) [%.2f W]"             <battery>                       (base,watt,a)           {mqtt="<[mysensor:06/02/17:state:default]"}

Number KWH2_base "VP total KWh (källaren) [%.2f KWh]"                   <battery>                       (base,kwh,a)            {mqtt="<[mysensor:06/04/17:state:default]"}

Number Temp_test "Temperatur [%.1f °C]"                                 <temperature>                   (test,temperature,a)    {mqtt="<[mysensor:06/10/00:state:default]"}

Number Hum_test "Relativ luftfuktighet [%.1f %%]"                       <humidity>                      (test,humidity,a)       {mqtt="<[mysensor:06/11/01:state:default]"}

Number Ahum_test "Absolut luftfuktighet [%.1f g/m³]"                                                    (test,ahumidity,a)

Number Dew_test "Daggpunk (test) [%.1f °C]"                                                             (test,dewpoint,a)

Switch sw1 "sw 1 [test]"  (test,sw,a) {mqtt=">[mysensor:03/01/02:command:ON:1],>[mysensor:03/01/02:command:OFF:0],<[mysensor:03/01/02:command:MAP(1.map)]"}

Switch sw2 "sw 2 [test]"  (test,sw,a) {mqtt=">[mysensor:03/02/02:command:ON:1],>[mysensor:03/02/02:command:OFF:0],<[mysensor:03/02/02:command:MAP(1.map)]"}

Switch sw3 "sw 3 [test]"  (test,sw,a) {mqtt=">[mysensor:03/03/02:command:ON:1],>[mysensor:03/03/02:command:OFF:0],<[mysensor:03/03/02:command:MAP(1.map)]"}

Switch sw4 "sw 4 [test]"  (test,sw,a) {mqtt=">[mysensor:03/04/02:command:ON:1],>[mysensor:03/04/02:command:OFF:0],<[mysensor:03/04/02:command:MAP(1.map)]"}

[Davy Vanherbergen]

Hi,

Can you check if the attached jar resolves the issue?

Davy

[daniel....@gmail.com]

Tested and seams to work fine! no repeated unsubscribe.

[Davy Vanherbergen]

Great! I'll create a pull request to get it included in the nightly build.

Davy