Self hosted myopenHAB does not switch items using Mobile App

Tags: #<Tag:0x00007f618476c0b8>

Using the OpenHAB mobile app (Both Android & IOS) connected local or remote displays the site map correctly. When connecting the app remote to my self hosted myopenHAB none of the switches (Control lights) work, on the local connection they work fine as well as previously on myopenhab.org. In the openhabcloud.cfg “mode=remote” is set. The Android app notifies “event subscription failed, widget refresh maybe impaired”, this is the only indication on an error as I have not found any obvious errors in the logs. On the webpage of myopenhab I see my Android device, can send notifications to the device and access my openhab dashboard remotely.

During installation had the following warning:

npm WARN bcrypt-cache@1.1.0 requires a peer of bcryptjs@^2.4.3 but none was installed.
npm WARN grunt-qunit-node@0.1.0 requires a peer of qunitjs@^2.0.0 but none was installed.

System setup:

  • Openhab and myopenhab in a separate Proxmox LXC containers running Debian 10.
  • Up-to-date OpenHABian stable version 2.5.5-1
  • Nginx with SSL and HAProxy on PFsense

Any suggestions welcome.

Do log entries in PFsense show trials of access ?
The URL that is entered for Account Linking contains the ( external ) DNS name of your server ?

Created a small test sitemap as follows:

sitemap Test label="Test" {
    Frame label="Remote switch testing" {
        Switch item=OUTCurtFrontUpLIV
    }
}

PFSense/HAProxy logging gives me 10k blocks of log, not sure why but this is what I related to to the sitemap:

Jun 18 10:44:50 Router haproxy[67871]: x.x.x.x:53084 [18/Jun/2020:10:44:50.416] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/8/8 200 820 - - ---- 5/5/2/3/0 0/0 "POST /rest/sitemaps/events/subscribe HTTP/1.1" 
Jun 18 10:44:50 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:44:50.470] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/8/8 200 1613 - - ---- 5/5/2/3/0 0/0 "GET /rest/sitemaps/Test/Test?includeHidden=true HTTP/1.1" 
Jun 18 10:44:51 Router haproxy[67871]: x.x.x.x:53078 [18/Jun/2020:10:44:32.672] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/543/19284 200 7347 - - CD-- 5/5/2/2/0 0/0 "GET /rest/sitemaps/events/c6aded4e-33f1-48b3-9e1a-304c8a09f336?sitemap=Condo&pageid=Condo HTTP/1.1" 
Jun 18 10:44:52 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:44:52.195] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/9/9 200 786 - - ---- 4/4/2/3/0 0/0 "GET /rest/items/OUTCurtFrontUpLIV HTTP/1.1" 
Jun 18 10:44:52 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:44:52.864] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/8/8 200 784 - - ---- 4/4/2/3/0 0/0 "GET /rest/items/OUTCurtFrontUpLIV HTTP/1.1" 
Jun 18 10:44:53 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:44:53.211] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/7/7 200 786 - - ---- 4/4/2/3/0 0/0 "GET /rest/items/OUTCurtFrontDwLIV HTTP/1.1" 
Jun 18 10:44:53 Router haproxy[67871]: x.x.x.x:10042 [18/Jun/2020:10:44:47.853] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/4103/5366 200 2867 - - CD-- 4/4/1/1/0 0/0 "GET /rest/sitemaps/events/6ec403f3-8f69-4392-8dc4-2766770a4520?sitemap=Condo&pageid=Condo HTTP/1.1" 
Jun 18 10:44:53 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:44:53.530] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/7/8 200 784 - - ---- 3/3/1/2/0 0/0 "GET /rest/items/OUTCurtFrontUpLIV HTTP/1.1" 
Jun 18 10:44:54 Router haproxy[67871]: x.x.x.x:53080 [18/Jun/2020:10:44:54.335] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/7/7 200 816 - - ---- 3/3/1/2/0 0/0 "POST /rest/sitemaps/events/subscribe HTTP/1.1" 
Jun 18 10:45:10 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:45:10.356] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/7/7 200 818 - - ---- 2/2/1/2/0 0/0 "POST /rest/sitemaps/events/subscribe HTTP/1.1" 
Jun 18 10:45:10 Router haproxy[67871]: x.x.x.x:53086 [18/Jun/2020:10:45:10.446] BlocsFrontend-WAN~ myopenhab_ipvANY/myopenhab-backend 0/0/0/7/7 200 1147 - - ---- 2/2/1/2/0 0/0 "GET /rest/sitemaps/Test/Test?includeHidden=true HTTP/1.1" 

The frontend uses SSL offloading, the backend I tried both to http://myopenhab.a.b:3000 and https://myopenhab.a.b (myopenhab Nginx install uses same SSL cert on local LAN) with same result. For internal routing the DNS resolver has host override for myopenhab.a.b

The url in openhab cloud is http://myopenhab.a.b:3000, it will not connect with https://myopenhab.a.b

I am not familiar with PFsense logs but according to the 200 code this looks like the access is not blocked but gratend, right.
What does the openhabcloud log show while you try to access the site map ?
E.g.:
/var/www/./openhab-cloud/logs/audit-2020-06-18-process-3000.log

2020-06-18 07:50:32:3232 audit: <...my-login-name...> | online | GET | /basicui/smarthome.css | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:32:3232 audit: <...my-login-name...> | online | GET | /basicui/roboto.css | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:32:3232 audit: <...my-login-name...> | online | GET | /basicui/material-icons.css | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:32:3232 audit: <...my-login-name...> | online | GET | /basicui/mdl/material.min.css | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:32:3232 audit: <...my-login-name...> | online | GET | /basicui/mdl/material.min.js | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:33:3333 audit: <...my-login-name...> | online | GET | /icon/calendar | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:33:3333 audit: <...my-login-name...> | online | GET | /icon/switch | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:33:3333 audit: <...my-login-name...> | online | GET | /icon/tv | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:33:3333 audit: <...my-login-name...> | online | POST | /rest/sitemaps/events/subscribe | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0
2020-06-18 07:50:34:3434 audit: <...my-login-name...> | online | GET | /rest/sitemaps/events/93341a8f-d31b-482e-9a58-c25512330330 | <xxx.xxx.xxx.xxx> | <myhost>.<mydomain> | Mozilla/5.0 (X11; Linux i686; rv:64.0) Gecko/20100101 Firefox/64.0

EDIT: Was stuck on empty log file until I figured out that log and config.json were owned by root, that fixed finally have audit logs with content. Comparing the logfile noticed that mine was showing “Undefined” instead of the IP address as in yours. Made the mistake of pointing internet traffic coming out of HAProxy to to http://myopenhab:3000 instead of https://myopenhab. That fixed the result of an on-off-on action now shows as follows but no joy yet:

2020-06-22 22:46:44:4444 audit: me@dom.com | online | GET | /rest/sitemaps/events/33e0569d-5356-4a06-b579-4bd3e5fa875b | 172.16.1.1 | myopenhab.dom.com | openHAB client for Android
2020-06-22 22:46:44:4444 audit: me@dom.com | online | GET | /rest/sitemaps/events/2556d7d2-abe6-4f56-ac1b-1ba46c799f31 | 172.16.1.1 | myopenhab.dom.com | openHAB client for Android
2020-06-22 22:46:47:4747 audit: me@dom.com | online | GET | /rest/items/OUTCurtFrontUpLIV | 172.16.1.1 | myopenhab.dom.com | openHAB client for Android
2020-06-22 22:46:48:4848 audit: me@dom.com | online | GET | /rest/items/OUTCurtFrontUpLIV | 172.16.1.1 | myopenhab.dom.com | openHAB client for Android
2020-06-22 22:46:49:4949 audit: me@dom.com | online | GET | /rest/items/OUTCurtFrontUpLIV | 172.16.1.1 | myopenhab.dom.com | openHAB client for Android

Did see some other message restarting the openhabcloud service:

Jun 22 21:03:11 myOpenHAB systemd[1]: Started node.js openhab cloud server.
Jun 22 21:03:13 myOpenHAB openhabcloud[25585]: Option polling duration is not valid. Please refer to the README.
Jun 22 21:03:13 myOpenHAB openhabcloud[25585]: (node:25585) DeprecationWarning: current URL string parser is deprecated, and will be removed in a futu
Jun 22 21:03:13 myOpenHAB openhabcloud[25585]: (node:25585) DeprecationWarning: current Server Discovery and Monitoring engine is deprecated, and will
Jun 22 21:03:13 myOpenHAB openhabcloud[25585]: (node:25585) DeprecationWarning: collection.ensureIndex is deprecated. Use createIndexes instead.

Not sure if the second line about polling is an issue?

And in the openhab-cloud-date-process-3000.log I see the following:

2020-06-22 23:25:00:000 info: openHAB-cloud: every5min statistics collection job started
2020-06-22 23:25:00:000 info: openHAB-cloud: every5min statistics collection job finished
2020-06-22 23:25:52:5252 debug: openHAB-cloud: Checking for offline openHABs (0)
2020-06-22 23:25:52:5252 debug: openHAB-cloud: Checking orphaned rest requests (2)
2020-06-22 23:26:52:5252 debug: openHAB-cloud: Checking for offline openHABs (0)
2020-06-22 23:26:52:5252 debug: openHAB-cloud: Checking orphaned rest requests (2)
2020-06-22 23:27:52:5252 debug: openHAB-cloud: Checking for offline openHABs (0)
2020-06-22 23:27:52:5252 debug: openHAB-cloud: Checking orphaned rest requests (4)
2020-06-22 23:28:52:5252 debug: openHAB-cloud: Checking for offline openHABs (0)
2020-06-22 23:28:52:5252 debug: openHAB-cloud: Checking orphaned rest requests (3)
2020-06-22 23:29:52:5252 debug: openHAB-cloud: Checking for offline openHABs (0)
2020-06-22 23:29:52:5252 debug: openHAB-cloud: Checking orphaned rest requests (3)
2020-06-22 23:30:00:000 info: openHAB-cloud: every5min statistics collection job started
2020-06-22 23:30:00:000 info: openHAB-cloud: every5min statistics collection job finished

Are the orphaned rest requests maybe a indication?

I did a check on orphaned processes that I see in my log file for today. Just counted the occurences which are either 0 or 1 time:

1098 debug: openHAB-cloud: Checking orphaned rest requests (0)
  97 debug: openHAB-cloud: Checking orphaned rest requests (1)

From comments in apps.js:

cancel restRequests that have become orphaned. For some reason neither close
nor finish is being called on some response objects and we end up hanging on
to these in our restRequests map. This goes through and finds those orphaned
responses and cleans them up, otherwise memory goes through the roof.

So it looks like it’s more or less normal that there are orphaned processes.

With regard to polling: Did you have a look to the README file ?

I haven’t been able to find a readme on the system that contains the polling duration, only location I found is in the app.js where it is set to 300. Changing this to 3, 30 and 30,000 did not change the error reported.