OH1 OwnTracks... not getting anywhere

Max_G · January 17, 2017, 3:29am

I am pulling my hair out – though it doesn’t fix anything

OH | mqttitude binding installed
openhab.conf changed to reflect lat lon radius
restarted OH
tried the set-up the examples in the wiki… no luck

OwnTracks is sending messages, has regions set-up… and seems to work just fine.
I can see the MQTT messages coming in like so:

owntracks/owntracks/maxg-iphone/event {"desc":"Home","t":"c","tst":1484616288,"acc":30,"lon":152.3707630859244,"_type":"transition","wtst":1484570767,"lat":-27.31735945681791,"event":"enter","tid":"MG"}
owntracks/owntracks/maxg-iphone {"conn":"w","t":"c","tst":1484616288,"acc":30,"alt":210,"vac":48,"lon":152.3707630859244,"_type":"location","lat":-27.31735945681791,"tid":"MG","batt":68}
owntracks/owntracks/maxg-iphone {"conn":"w","tst":1484616290,"vac":48,"acc":50,"alt":2253,"lon":152.3871252314675,"_type":"location","lat":-27.32542779299181,"tid":"MG","batt":68}
owntracks/owntracks/maxg-iphone/event {"desc":"Home","t":"c","tst":1484616290,"acc":50,"lon":152.3871252314675,"_type":"transition","wtst":1484570767,"lat":-27.32542779299181,"event":"leave","tid":"MG"}
owntracks/owntracks/maxg-iphone {"conn":"w","t":"c","tst":1484616290,"acc":50,"alt":2253,"vac":48,"lon":152.3871252314675,"_type":"location","lat":-27.32542779299181,"tid":"MG","batt":68}
owntracks/owntracks/maxg-iphone {"cog":92,"conn":"w","acc":10,"lon":152.3707868067104,"vel":0,"_type":"location","batt":68,"vac":16,"lat":-27.31763090475213,"tst":1484616303,"alt":198,"tid":"MG"}
owntracks/owntracks/maxg-iphone/event {"desc":"Home","t":"c","tst":1484616303,"acc":10,"lon":152.3707868067104,"_type":"transition","wtst":1484570767,"lat":-27.31763090475213,"event":"enter","tid":"MG"}
owntracks/owntracks/maxg-iphone {"cog":92,"conn":"w","acc":10,"lon":152.3707868067104,"vel":0,"_type":"location","batt":68,"vac":16,"lat":-27.31763090475213,"t":"c","tst":1484616303,"alt":198,"tid":"MG"}
owntracks/owntracks/maxg-iphone {"tst":"1484616283","_type":"lwt"}

Seems OK…
in .items I have:


Number   GeoLoc_MaxHomeM	"Max @ Home manual [%s]"	{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone"}
Switch   GeoLoc_MaxHome		"Max @ Home [%s]"		{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:home"}
String   GeoLoc_MaxHome2	"Max @ Home (2) [%s]"		{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:home"}
String   GeoLoc_MaxHome3	"Max @ Home (3) [%s]"		{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:home"}
String   GeoLoc_Coominya	"Car is in Coominya [%s]"	{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:Coominya"}

to test a variation of Switch, String, Number items… no luck here

in .sitemap I have:

        Text   item=GeoLoc_MaxHomeM	icon="present"
        Switch item=GeoLoc_MaxHome	icon="present"
        Text   item=GeoLoc_MaxHome2	icon="present"
        Text   item=GeoLoc_MaxHome3	icon="present"
        Switch item=GeoLoc_Coominya

What am I missing?
Any hints appreciated.

More information: just discovered this error:

sudo tail -f /var/log/openhab/openhab.log | stdbuf -o0 grep "mqtt"
2017-01-17 13:32:53.919 [ERROR] [i.internal.GenericItemProvider] - Binding configuration of type 'mqttitude' of item ‘GeoLoc_MaxHomeM‘ could not be parsed correctly.
        at org.openhab.binding.mqttitude.internal.MqttitudeGenericBindingProvider.validateItemType(MqttitudeGenericBindingProvider.java:45) ~[na:na]
2017-01-17 13:32:53.926 [ERROR] [i.internal.GenericItemProvider] - Binding configuration of type 'mqttitude' of item ‘GeoLoc_MaxHome2‘ could not be parsed correctly.
        at org.openhab.binding.mqttitude.internal.MqttitudeGenericBindingProvider.validateItemType(MqttitudeGenericBindingProvider.java:45) ~[na:na]
2017-01-17 13:32:53.932 [ERROR] [i.internal.GenericItemProvider] - Binding configuration of type 'mqttitude' of item ‘GeoLoc_MaxHome3‘ could not be parsed correctly.
        at org.openhab.binding.mqttitude.internal.MqttitudeGenericBindingProvider.validateItemType(MqttitudeGenericBindingProvider.java:45) ~[na:na]
2017-01-17 13:32:53.939 [ERROR] [i.internal.GenericItemProvider] - Binding configuration of type 'mqttitude' of item ‘GeoLoc_Coominya‘ could not be parsed correctly.
        at org.openhab.binding.mqttitude.internal.MqttitudeGenericBindingProvider.validateItemType(MqttitudeGenericBindingProvider.java:45) ~[na:na]

Max_G · January 17, 2017, 3:51am

Rather than editing my original post again… here the update:

Using anything but a Switch item, caused the parse error!

However, still no switch action on the sitemap, when publishing enter and leave messages via MQTT.

ben_jones12 · January 17, 2017, 3:58am

A few things;

1/ you don’t need the lat/lon/radius in your openhab.cfg if you are using regions in the Owntracks app - I am not sure but I think if they are present the binding might ignore the /event messages. Try removing them, and your _Manual item to see if that helps.
2/ the region name in your item bindings doesn’t match the region name (desc) in the app -> “home” != "Home"
3/ enable trace logging for the mqttitude binding and you should get more information about what the binding is receiving and doing.

Hope this helps!
Ben

Max_G · January 17, 2017, 4:26am

Thanks, Ben…

and yes, I figured the h|H ome mistake while re-reading my post (it is like talking to yourself and checking what you’re saying)

added this to /etc/openhab/logback.xml

<logger name="org.openhab.binding.mqttitude" level="DEBUG" />

removed manual mode settings from openhab.conf
restarted openhab

openhab.log shows this:

2017-01-17 14:12:16.112 [DEBUG] [.m.internal.MqttitudeActivator] - Mqttitude binding has been started.
2017-01-17 14:12:16.201 [DEBUG] [.b.m.internal.MqttitudeBinding] - Registering Mqttitude consumer for owntracks/owntracks/maxg-iphone/event (on mosquitto)
2017-01-17 14:12:16.203 [DEBUG] [.b.m.internal.MqttitudeBinding] - Activating Mqttitude binding

but nothing further is logged, when I publish (either enter | leave):

owntracks/owntracks/maxg-iphone/event {"desc":"Home","t":"c","tst":1484616288,"acc":30,"lon":152.3707630859244,"_type":"transition","wtst":1484570767,"lat":-27.31735945681791,"event":"enter","tid":"MG"}
owntracks/owntracks/maxg-iphone/event {"desc":"Home","t":"c","tst":1484616290,"acc":50,"lon":152.3871252314675,"_type":"transition","wtst":1484570767,"lat":-27.32542779299181,"event":"leave","tid":"MG"}

so… .items:

Switch   GeoLoc_MaxHome		"Max @ Home [%s]"		{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:Home"}
Switch   GeoLoc_Coominya	"Car is in Coominya [%s]"	{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:Coominya"}

and .sitemap:

        Switch item=GeoLoc_MaxHome	icon="present"
        Switch item=GeoLoc_Coominya	icon="present"

… all clean…
However, neither event.log nor openhab.log show any activity when publishing.

Max_G · January 17, 2017, 5:00am

Is there a TRACE for debugging?
seems to be when looking at the source:

logger.trace("Location {} event is for region '{}', ignoring", event, desc);

When I checked here (though for OH2) is only has 4 levels: ERROR, WARN, INFO, DEBUG.

Have now changed logging to TRACE; did not throw an error, but does nothing more then DEBUG as shown before.

BTW: the binding wiki says both manual and regions cen be used at the same time.

My ultimate goal is to show on the sitemap something like:
Max is 78km away from home.
which should be updated as messages are received.
However, I thought I start with the example first.

ben_jones12 · January 17, 2017, 6:03am

Do you have any ACLs setup on your MQTT broker? I think with TRACE logging you should see any messages being received by the binding, which looks like it is subscribing to the right topic at least.

Max_G · January 17, 2017, 6:33am

Thanks for getting back to me.
Short answer: No.

I have a simple (default) mqtt set-up that works…
Nothing but default settings in OH and mosquitto; no password, etc.
Exception from default: I do have a second listener defined on port 8883; though TLS)

OH and mqtt is working; e.g.

2017-01-17 16:23:58 - Network_Router_LAN state updated to ON
2017-01-17 16:23:58 - Network_ATA state updated to ON
2017-01-17 16:24:00 - Hub_BorePump_Demand state updated to ON
2017-01-17 16:24:00 - Bore_Pump_Status state updated to ON
2017-01-17 16:24:01 - mobMaxG state updated to present
2017-01-17 16:24:14 - Weather_Humidity state updated to 45
2017-01-17 16:24:14 - Weather_Temperature state updated to 32
2017-01-17 16:24:14 - Weather_LastUpdate state updated to 2017-01-17T16:24:14
2017-01-17 16:24:15 - Hub_BorePump_Demand state updated to ON
2017-01-17 16:24:15 - Bore_Pump_Status state updated to ON
2017-01-17 16:24:16 - Tank_Irrigation_Demand state updated to ON
2017-01-17 16:24:17 - Tank_Irrigation_Level state updated to 2

E.g. Tank, Bore, Hub are all MQTT message based.

The iPhone at present connects via local WiFi.
However, I publish the originally received messages for enter and leave to test mqttitude in OH.
Subscribing to the same topic (via terminal) will show the very same message.

Yes, I am not sure why I have owntracks/owntracks in the topic; as the examples I see do not.
But this does not matter ATM, nor does not seem to be the problem.
As you said: it seems to register / subscribe to this msg.

ben_jones12 · January 17, 2017, 7:18am

Yep so checking the source code (which I wrote many years ago ;)) there is definitely trace logging configured to help debug these sorts of issues. Any message received by the binding subscription is logged via;

logger.trace("Message received on topic {}: {}", topic, decoded);

The fact you are not seeing these either means your logging is not configured correctly, or for some reason the messages are not getting thru to the binding. The fact the Registering Mqttitude consumer for xxx is being logged seems to mean your item config is correct.

I would focus on the logging side of things I think.

Max_G · January 17, 2017, 7:27am

Thanks… will do…
though I do not know what to look for, this is my entry:

<logger name="org.openhab.binding.mqttitude" level="TRACE" />

since these entries do work (enabled disabled weather and exec):

        <!-- 170171 MaxG log levels are: OFF, ERROR, WARN, INFO, DEBUG, TRACE -->

        <!-- 160626 MaxG enabled logging for weather binding -->
        <!-- logger name="org.openhab.binding.weather" level="DEBUG" /-->

        <!-- 160730 MaxG added to log test msgs to info -->
        <!-- logger name="org.openhab.model.script.test" level="DEBUG" /-->

        <!-- 160918 MaxG added to log exec binding -->
        <!-- logger name="org.openhab.binding.exec" level="DEBUG" /-->

Can someone please confirm, whether I named the log entry for mqttitude correctly?

ben_jones12 · January 17, 2017, 8:24am

That logging config looks fine. I just checked again and the only place that there is trace logging is inside the MQTT consumer, meaning if you don’t receive any messages you won’t see anything extra in the logging.

So it perhaps means that for some reason openHAB isn’t receiving those pubs to that topic.

Can you do a mosquitto_sub using the same user/pwd as openHAB uses and then do your test pub to that topic and make sure it is appearing?

Max_G · January 17, 2017, 9:36am

I think I did not specify a user / pw for OH to connect to.
my openhab.conf mqtt section is:

mqtt:mymosquitto.url=tcp://localhost:1883
mqtt:mymosquitto.clientId=openhab
mqtt:mymosquitto.qos=0
mqtt:mymosquitto.retain=true
mqtt:mymosquitto.async=true

there is also no longer a mqttitude config (removed earlier on your advice)

I quickly created a String item…

String mqttitudeTest "mqttitudeTest [%s]" {mqtt="<[mymosquitto:owntracks/owntracks/maxg-iphone/event:state:default]"}

.sitemap

        Text item=mqttitudeTest

and it logs:

2017-01-17 19:33:11 - mqttitudeTest state updated to {"desc":"Home","t":"c","tst":1484616290,"acc":50,"lon":152.3871252314675,"_type":"transition","wtst":1484570767,"lat":-27.32542779299181,"event":"leave","tid":"MG"}

so OH can subscribe / work this particular publish command.

Also, re-installed the binding with apt-get, same log msgs and behaviour. My initial install was simply dropping the binding into ‘addons’.

Max_G · January 17, 2017, 11:33am

Are we on the same page? OH 1.8.3
Just saw another post having the same issue in 1.9.0. (OH2).
Maybe this is related?

westermarck · January 17, 2017, 12:53pm

When I add a debug item that subscribes to messages on the same topic I get messages so that would, in my case, rule out a configuration error in mqtt.conf.

I haven’t moved the phone out of the geofence or spoofed any MQTT-messages so I in order to confirm that the MQTT configuration works I subscribed directly to the device topic and not to the /event topic.

13:32:02.523 [INFO ] [marthome.event.ItemStateChangedEvent] - mqttitudeTest changed from {"_type":"location","tid":"ik","acc":9,"batt":67,"conn":"w","doze":false,"lat":XX.XXXXXXX,"lon":YY.YYYYYYY,"tst":1484655994} to {"_type":"location","tid":"ik","acc":30,"batt":67,"conn":"w","doze":false,lat":XX.XXXXXXX,"lon":YY.YYYYYYY,"tst":1484656321}

Debug Item:

String mqttitudeTest "mqttitudeTest [%s]" {mqtt="<[mqttloc:owntracks/<user>/<device>:state:default]"}

ben_jones12 · January 17, 2017, 7:03pm

I personally am running 1.8.3. Sounds like Fredrik has got his issue sorted. Since you have proven that your MQTT broker is receiving those messages I think the only thing left is your item config (but I am not sure what).

Can you post your full items config currently? I would suggest paring it right back to a single Switch item to remove any confusion and see if we can make any progress with that.

Max_G · January 17, 2017, 10:55pm

… was only asking…

.sitemap

        Switch item=GeoLoc_MaxHome	icon="present"

.items

Switch   GeoLoc_MaxHome		"Max @ Home [%s]"		{mqttitude="mosquitto:owntracks/owntracks/maxg-iphone/event:Home"}

logback.xml

<logger name="org.openhab.binding.mqttitude" level="TRACE" />

no entry related to mqttitude in openhab.conf
mosquitto (has been and) is running nicely
mqttitude does not seem to process the messages.

After reducing the items config to one switch, I rebooted the rPi (just to be sure)

On a side note: if you have 1.8.3 running, why not check the log level by adding TRACE to the logger, and see, what the outcome of openhab.log is. Even if I set it to TRACE it says DEBUG in the log. (The same with the EXEC and Yahoo weather binding); so I doubt that the openhab.log will show TRACE as a word; whether this affects its inner working; e.g. whether it does actually do TRACE I cannot tell.

In any case, thank you for your continued help with this issue.

@westermarck: As you can see in a previous post, I have done exactly the same. In my case (as I suspect in yours) mosquitto is working. But the mqttitude binding, despite subscribing to the OwnTracks topic does not seem to process any of it.

ben_jones12 · January 17, 2017, 10:56pm

And you are still seeing the mqttitude debug message that it is subscribing to the appropriate topic?

Max_G · January 17, 2017, 11:21pm

yes…

2017-01-18 07:54:27.398 [INFO ] [penhab.io.rest.RESTApplication] - Stopped REST API
2017-01-18 07:55:03.650 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v1.8.3).
2017-01-18 07:55:08.763 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - mDNS service has been started
2017-01-18 07:55:09.003 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - Service Discovery initialization completed.
2017-01-18 07:55:09.025 [INFO ] [.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-01-18 07:55:09.030 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting MQTT broker connection 'mymosquitto'
2017-01-18 07:55:18.396 [INFO ] [penhab.io.rest.RESTApplication] - Started REST API at /rest
2017-01-18 07:55:23.961 [INFO ] [.o.u.w.i.servlet.WebAppServlet] - Started Classic UI at /classicui/openhab.app
2017-01-18 07:55:26.686 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'max01.items'
2017-01-18 07:55:27.326 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'lights.items'
2017-01-18 07:55:27.522 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'groups.items'
2017-01-18 07:55:27.666 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'openings.items'
2017-01-18 07:55:29.441 [DEBUG] [.m.internal.MqttitudeActivator] - Mqttitude binding has been started.
2017-01-18 07:55:29.504 [DEBUG] [.b.m.internal.MqttitudeBinding] - Registering Mqttitude consumer for owntracks/owntracks/maxg-iphone/event (on mosquitto)
2017-01-18 07:55:29.507 [DEBUG] [.b.m.internal.MqttitudeBinding] - Activating Mqttitude binding
2017-01-18 07:55:29.728 [INFO ] [.b.a.internal.bus.AstroBinding] - AstroConfig[latitude=-27.3164855,longitude=152.3701568,interval=60,systemTimezone=Austral$
2017-01-18 07:55:29.742 [INFO ] [.p.rrd4j.internal.RRD4jService] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 ar$
2017-01-18 07:55:29.905 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'logging.persist'
2017-01-18 07:55:30.024 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-01-18 07:55:30.064 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'db4o.persist'
2017-01-18 07:55:30.105 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-01-18 07:55:30.659 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'exec.persist'
2017-01-18 07:55:30.808 [WARN ] [o.p.m.i.MqttPersistenceService] - mqtt-persistence:broker
2017-01-18 07:55:30.812 [WARN ] [o.p.m.i.MqttPersistenceService] - mqtt-persistence:topic
2017-01-18 07:55:30.815 [WARN ] [o.p.m.i.MqttPersistenceService] - mqtt-persistence:message
2017-01-18 07:55:31.285 [INFO ] [o.o.b.w.i.common.WeatherConfig] - LocationConfig[providerName=YAHOO,language=en,updateInterval=10,latitude=<null>,longitude$
2017-01-18 07:55:32.750 [INFO ] [.b.a.internal.job.JobScheduler] - Scheduled a daily job at midnight for astro calculation
2017-01-18 07:55:32.765 [INFO ] [.b.a.internal.job.JobScheduler] - Scheduled astro job with interval of 60 seconds

ben_jones12 · January 17, 2017, 11:22pm

I am at a loss then sorry

Max_G · January 17, 2017, 11:35pm

That’s OK… appreciate your help…

Will move to plan B – calculating the distance, etc via captured mosquitto strings and rules

Maybe you (or someone else) can clarify one thing:
If logging is set to TRACE (n logbakc.xml), does it show as TRACE or DEBUG in the openhab.log?

ben_jones12 · January 17, 2017, 11:57pm

I am close to 100% certain it will be shown as TRACE.

It is a shame, as this binding has been working flawlessly for me for years. Can’t understand why you are having such troubles!