Problem with MQTT binding, Doesnt seam to register UNSUBACK?

274 views
Skip to first unread message

daniel....@gmail.com

unread,
Jul 24, 2014, 6:35:18 AM7/24/14
to ope...@googlegroups.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?

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

unread,
Jul 29, 2014, 3:00:56 PM7/29/14
to ope...@googlegroups.com, daniel....@gmail.com
The problem exists in latest nightly also.

Davy Vanherbergen

unread,
Jul 30, 2014, 4:40:29 AM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
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

unread,
Jul 30, 2014, 4:58:47 AM7/30/14
to ope...@googlegroups.com, 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.
screen.log

daniel....@gmail.com

unread,
Jul 30, 2014, 5:04:58 AM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
Including the logfile again, Somehow it got in a wierd order; sorry!

Here is the correct one!
screen_all.log

Davy Vanherbergen

unread,
Jul 30, 2014, 5:12:55 AM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
Thanks, I'll investigate and keep you posted.

daniel....@gmail.com

unread,
Jul 30, 2014, 7:00:16 AM7/30/14
to ope...@googlegroups.com, 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

unread,
Jul 30, 2014, 5:53:52 PM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
Hi,

Can you check if the attached jar resolves the issue?

Davy
org.openhab.binding.mqtt-1.6.0-SNAPSHOT.jar

daniel....@gmail.com

unread,
Jul 30, 2014, 6:12:11 PM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
Tested and seams to work fine! no repeated unsubscribe.

Davy Vanherbergen

unread,
Jul 30, 2014, 6:19:38 PM7/30/14
to ope...@googlegroups.com, daniel....@gmail.com
Great! I'll create a pull request to get it included in the nightly build.

Davy
Reply all
Reply to author
Forward
0 new messages