Domoticz

Posted: **Sunday 11 February 2018 23:53**

I have tested the manual "wl -i eth1 assoclist;wl -i eth2 assoclist" command from /home/hjz/ and as root (with different id_rsa & pub).

They both work fine from the command line (also no error in the router logging). But I get the same error within the running domoticz: Error getting data from router: b'sh: wl: not found\nsh: wl: not found\n

I have also given the keys different permissions and owners, no change. I don't think it has to do with the keys (they work fine from command line)

Can it have something to do with installed python versions? I have both v2.7 as v3.6.3 installed?

Posted: **Monday 12 February 2018 20:54**

I have been trying to reproduce your error, but can only get the test script (below) to fail if i make the authentication fail on purpose. Those failures will not generate the "b'sh: wl: not found\nsh: wl: not found\n" error you described. Which supports your analysis that the key files should not be causing this. However, i am unable to make the test script fail on my setup. Maybe you can try it using python 3.6 (i'm on 3.4)? I didn't test against stock asuswrt either.

I ran it from the command line as

Code: Select all

python2.7 testscript.py

and

Code: Select all

python3.4 testscript.py

to have it run in different versions.

testscript.py:

Code: Select all

import subprocess
host="192.168.1.1"
user="root"
idfile="/root/.ssh/id_rsa"

ssh = subprocess.Popen(["ssh", "-o", "ConnectTimeout=3", user+"@"+host, "-i", idfile, "wl -i eth1 assoclist;wl -i eth2 assoclist"], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
ssh_out, ssh_err = ssh.communicate()
print("output:", ssh_out)
print("error:", ssh_err)

(change variables to match your setup)

Silly question: are absolutely sure your plugin configuration is the same as the tests you are doing from the command line? There's no old ip adres of the router in there or some accidental special characters in the mac addresses field?
Have you tried removing the plugin form the configuration en reconfiguring it?

I'm grasping straws here

Posted: **Monday 12 February 2018 21:18**

Without testing the python version, you can also test this from the command line (change ip address, username and key file path to match yours)

Code: Select all

sudo ssh [email protected] -i /root/.ssh/id_rsa "wl -i eth1 assoclist;wl -i eth2 assoclist"

If this (or the script in my previous post) also generates an error, could you post the exact command you tried and a printscreen of your plugin config?

The only two things i can come up with that would generate the 'wl not found' errors would be:
- the user id on the router can't access the wl command. Could be a limited user or different path in it's environment (very unlikely given your previous results from the command line)
- the plugin is connecting to something else than your asus router

I'm not sure how the plugin would handle special characters in the configuration screen. Maybe some special character can mess up the generated ssh code and make it connect to something different. Seems very unlikely but then again, must bugs are... until they are discovered

Posted: **Monday 12 February 2018 22:55**

EscApe wrote: ↑Monday 12 February 2018 21:18 Without testing the python version, you can also test this from the command line (change ip address, username and key file path to match yours)
Code: Select all
sudo ssh [email protected] -i /root/.ssh/id_rsa "wl -i eth1 assoclist;wl -i eth2 assoclist"
If this (or the script in my previous post) also generates an error, could you post the exact command you tried and a printscreen of your plugin config?

The only two things i can come up with that would generate the 'wl not found' errors would be:
- the user id on the router can't access the wl command. Could be a limited user or different path in it's environment (very unlikely given your previous results from the command line)
- the plugin is connecting to something else than your asus router

I'm not sure how the plugin would handle special characters in the configuration screen. Maybe some special character can mess up the generated ssh code and make it connect to something different. Seems very unlikely but then again, must bugs are... until they are discovered

I also just recently switched back to stock Asus firmware because of AiMesh (AC5300).

Code: Select all

sudo ssh [email protected] -i /root/.ssh/id_rsa "wl -i eth1 assoclist;wl -i eth2 assoclist"

Using exactly the same command this is the result:

Code: Select all

sh: wl: not found
sh: wl: not found

Doing it step by step works, so the wl command is there:

1. sudo ssh [email protected] (It logs in correctly without asking for a pass)
2. wl -i eth1 assoclist;wl -i eth2 assoclist (produces both lists in the shell)

So somehow stock Asus firmware messes things up.

Posted: **Monday 12 February 2018 23:01**

wl is located in /usr/sbin.

running it like this works:

Code: Select all

sudo ssh [email protected] -i /root/.ssh/id_rsa "/usr/sbin/wl -i eth1 assoclist;/usr/sbin/wl -i eth2 assoclist

Posted: **Monday 12 February 2018 23:27**

I will check your input tomorrow evening, seems more our joining to solve this puzzle

This evening i did check the last beta from Merlin, also produced the exact same error (that was RT-AC68U_384.3_beta2)

Posted: **Tuesday 13 February 2018 7:01**

I ran the test scripts:

Last login: Mon Feb 12 20:48:52 2018 from 192.168.1.5
hjz@domoticz:~$ sudo ssh [email protected] -i /root/.ssh/id_rsa "wl -i eth1 assoclist;wl -i eth2 assoclist"
[sudo] password for hjz:
sh: wl: not found
sh: wl: not found
hjz@domoticz:~$ sudo ssh [email protected]
HJZ@RT-AC68U:/tmp/home/root# wl -i eth1 assoclist;wl -i eth2 assoclist
assoclist 00:04:20:F1:B9:4A
assoclist 94:9A:A9:62:49:EF
assoclist 00:60:34:0D:1C:8E
assoclist 9C:D3:5B:04:8A:68
assoclist 94:E9:6A:3F:7A:3B
assoclist 9C:D3:5B:04:89:12
assoclist 2C:9E:FC:93:A0:DA
assoclist F0:24:75:B7:D4:87
HJZ@RT-AC68U:/tmp/home/root# exit
Connection to 192.168.1.1 closed.
hjz@domoticz:~$ ^C
hjz@domoticz:~$ sudo ssh [email protected] -i /root/.ssh/id_rsa "/usr/sbin/wl -i eth1 assoclist;/usr/sbin/wl -i eth2 assoclist
>

See result. The first command gives the wl not found error. The command with the usr/sbin/wl gives no errors!

Posted: **Tuesday 13 February 2018 17:19**

@tezzlicious and hjzwiers

That's some really useful info. Thanks! Learned something new: the environment (like PATH variable) in a remote command is not necessarily the same as a interactive session.

I changed the plugin to first set a PATH, so hopefully it will now always find the wl command in various firmwares. Please try the updated plugin in the top post.
Made a few other (minor) changes.

Posted: **Tuesday 13 February 2018 17:32**

Have you tried the built in ping function? just give the clients some specific addresses in dhcp. and ping for them with System alive checker(ping)

Posted: **Tuesday 13 February 2018 17:37**

Thanks for your suggestion. I use the router solution because it doesn't need to ping the devices themselves. Responding to pings would drain the battery and is unnecessary.

Posted: **Tuesday 13 February 2018 20:52**

Making progress

I have two keys now, one from root and one from the user hjz. I used the hjz one, tested the connection from the command line, then installed the new version of Presence:

Because of the errors in the logging I thought it was not working. But I just tested by putting phones in airplane mode, and it"s working!!!! Only the error messages keep coming in intervals of usually 2 to 5 minutes.

This log from the router:
Child connection from 192.168.1.10:39204
Feb 13 20:37:45 dropbear[11645]: Pubkey auth succeeded for 'HJZ' with key sha1!! c9:23:66:f9:1b:88:9f:a2:2d:2e:fe:80:09:3d:67:32:bb:44:d9:af from 192.168.1.10:39204
Feb 13 20:37:45 dropbear[11645]: User HJZ executing 'export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH;wl -i eth1 assoclist;wl -i eth2 assoclist'
Feb 13 20:37:45 dropbear[11645]: Exit (HJZ): Disconnect received

This is the error from Domoticz:
2018-02-13 20:37:28.432 Error: (Detect_phones) Error getting data from router: b'Connection timed out during banner exchange\r\n'
2018-02-13 20:37:28.432 Error: (Detect_phones) No list of connected WLAN devices from router

The interval between the error message in Domoticz is approx 1 to 5 minutes, while I see the connection on the router every 10 seconds (the default)

Posted: **Tuesday 13 February 2018 21:30**

Edit: misread your post. Glad it is working (most of the time

).

I will do a little digging into this type of timeout. The connection timout in the plugin is kept quite short so it never floods the (single threaded) event system in Domoticz. Maybe you can also do some searches and tests. It’s tough to troubleshoot an issue I cannot reproduce.

Not the progress i was hoping for

The time on your error is different from the domoticz log entry. Could it be the plugin is functioning correctly in between the errors? Are de Domoticz devices created and updated if you disable/enable Wi-Fi on your phone?

Since I am not running the stock asuswrt and the plugin is running just fine on my setup I can
not test the following myself... would you be willing to run Domoticz with -loglevel 0 switch (debug logging)? You will get a bit more info from the plugin.

Posted: **Tuesday 13 February 2018 22:00**

Thanks for your effort. I have no problem doing any test, but I have no clue how to test this or get relevant data ....... I will google a bit as well.

Posted: **Tuesday 13 February 2018 23:09**

I started reading about debugging and then I checked the domoticz.sh file. I installed Domoticz (on Linux 17.10 NUC platform) with the command

sudo curl -L install.domoticz.com | bash

Seems it fills in a default user pi !!!!

I changed this to hjz, and all the errors have reduced ....

Any tips on debugging welcome!

Posted: **Wednesday 14 February 2018 12:14**

@hjzwiers

I'm not sure if the "Connection timed out during banner exchange" is related to Domoticz. It's seems te be an error that can occur if ssh server and client have soms compatibility issues or if the network is to slow or unstable. Timeouts can also occur when the client or server machine is to busy. Are you running any other packages on the router (like mediaserver)?

Since the Domoticz plugin is running a linux ssh command and the linux ssh command returns the error i would look at OS (linux) level first. Maybe we can eliminate Domoticz as a suspect.

I have written a little testscript that you can run from the command line and which does the same ssh requests as the plugin. It will show you the time taken for the ssh task, the number of errors since it was started, the maximum time a ssh task took and a (small portion of) the output. You can run it for a while to see when if the times are longer than expected. It will run forever or until you press Ctrl-C.

It will crash if the connection is timed out (failure to connect at all), but your error message is caused be a different type of timeout.

Please change the variables to match your setup and run it with

Code: Select all

python3 sshspeedtest.py

sshspeedtest.py:

Code: Select all

#!/bin/python3
import subprocess
from time import time, sleep
from datetime import timedelta

host="192.168.1.1"
user="<username>"
idfile="<full path to key file>"

errors = 0
maxtime = timedelta(seconds=0)

while True:
    start=time()
    ssh = subprocess.Popen(["ssh", "-o", "ConnectTimeout=1", user+"@"+host, "-i", idfile, "export PATH=/usr/sbin:$PATH;wl -i eth1 assoclist;wl -i eth2 assoclist"], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
    ssh_out, ssh_err = ssh.communicate()
    timespend=timedelta(seconds=time()-start)
    if timespend > maxtime: maxtime = timespend
    if ssh_err:
        errors = errors + 1
        print(str(timespend) + " (errors=" + str(errors) + ", maxtime=" + str(maxtime) + ") > error:" + ssh_err.decode('utf-8'))
    else:
        print(str(timespend) + " (errors=" + str(errors) + ", maxtime=" + str(maxtime) + ") > data:" + ssh_out.decode('utf-8')[:27])
    sleep(2)

Here's a sample of the output on my raspberry pi. As you can see it usually takes about half a second to process the entire ssh command (connect, run and disconnect). Are you numbers close to that?

Code: Select all

0:00:00.506418 (errors=0, maxtime=0:00:00.506418) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.533610 (errors=0, maxtime=0:00:00.533610) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.500556 (errors=0, maxtime=0:00:00.533610) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.509922 (errors=0, maxtime=0:00:00.533610) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.544163 (errors=0, maxtime=0:00:00.544163) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.528557 (errors=0, maxtime=0:00:00.544163) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.535204 (errors=0, maxtime=0:00:00.544163) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.512885 (errors=0, maxtime=0:00:00.544163) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.543159 (errors=0, maxtime=0:00:00.544163) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.550029 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.501367 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.511868 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.508022 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.509367 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA
0:00:00.503087 (errors=0, maxtime=0:00:00.550029) > data:assoclist 00:04:20:F5:AA:AA

*MAC addresses have been changed to protect the innocent

Posted: **Wednesday 14 February 2018 20:29**

I ran your script (the ssh = subprocess.Popen line was not copied right but i corrected it based on the plugin)

These are the times:

0:00:00.305547 (errors=0, maxtime=0:00:00.305547) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.267185 (errors=0, maxtime=0:00:00.305547) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.273844 (errors=0, maxtime=0:00:00.305547) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.284461 (errors=0, maxtime=0:00:00.305547) > data:assoclist 00:04:20:F1:B9:4A
0:00:03.017488 (errors=1, maxtime=0:00:03.017488) > error:Connection timed out during banner exchange

0:00:00.257058 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.296393 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.278588 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.315892 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.290391 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.300130 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.286834 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.271826 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.250269 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.265146 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.282633 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.285354 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.258707 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.261462 (errors=1, maxtime=0:00:03.017488) > data:assoclist 00:04:20:F1:B9:4A
0:00:03.016411 (errors=2, maxtime=0:00:03.017488) > error:Connection timed out during banner exchange

0:00:03.021926 (errors=3, maxtime=0:00:03.021926) > error:Connection timed out during banner exchange

0:00:00.301796 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.259850 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.315365 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.262948 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.304390 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.311065 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.294761 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.273255 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.276446 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.259544 (errors=3, maxtime=0:00:03.021926) > data:assoclist 00:04:20:F1:B9:4A

normally approx 0,3 sec, then the occasional time out

I increased the timeout period to see where the max is at

0:00:00.584127 (errors=0, maxtime=0:00:00.584127) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.284415 (errors=0, maxtime=0:00:00.584127) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.307799 (errors=0, maxtime=0:00:00.584127) > data:assoclist 00:04:20:F1:B9:4A
0:00:05.262087 (errors=0, maxtime=0:00:05.262087) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.304684 (errors=0, maxtime=0:00:05.262087) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.288296 (errors=0, maxtime=0:00:05.262087) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.291067 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:05.257716 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.287531 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.315035 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.297320 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.279320 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.972532 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.283783 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.277077 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:05.271446 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.278571 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A
0:00:00.258991 (errors=0, maxtime=0:00:05.306149) > data:assoclist 00:04:20:F1:B9:4A

Again typically around 0,3 but occasionally upto almost 6 seconds.

Guess its clear where the issue is ...... now te question why. Between making the contact to the router to closing takes about 1 second in the router log, must be in the NUC. Thanks for your help (you should add the test file to the zip

)

Next search. If there are any ideas they are welcome!!

Posted: **Wednesday 14 February 2018 21:02**

At least you can eliminate Domoticz and it's plugin system from further testing.

I ran some tests on my raspberry and asus router. It was rock solid at around 0,5 seconds under normal circumstances. Even if i maxed out the cpu and io on both raspberry and router (using the linux 'stress' utility) i could never get it to throw an error. The responsetimes suffered severely, but never got above 3 seconds. So other running processes running on the router or nuc are also unlikely to be causing the error.

The SSH daemon (dropbear) or client versions might still be a factor.
You might also want to try another router firmware, just to see if that makes any difference.
The network stability is another possible source. Is the nuc connecting wirelessly? Then try a wired connection, even if it's just for testing. If it is hardwired, then you might have to get into network diagnostics. I can't help you with that.

Thanks for pointing out the copy-paste error. I have corrected the code in the test script.

Posted: **Thursday 15 February 2018 22:41**

I have tried to optimize the network settings

RSAAuthentication yes
PubkeyAuthentication yes
UseDNS no
GSSAPIAuthentication no
Allowed users hjz

Its not due to packet loss or the connection, ping shows good statistics.
--- 192.168.1.1 ping statistics ---
539 packets transmitted, 539 received, 0% packet loss, time 550586ms
rtt min/avg/max/mdev = 0.220/0.296/0.654/0.033 ms

Any other tricks in the book?

Posted: **Monday 19 February 2018 22:27**

I put debian jessie on the nuc and downloaded the RTL8168 driver (Linux by default puts the 8169 driver on)

I changed the ac68u firmware to 380.69.

No more errors in the speedtest (<1sec)

So there is a clear relation to the router firmware as well.

Posted: **Tuesday 20 February 2018 20:02**

Thank you for this great script.
My router is type AC86U.
I had a problem with the wl command. Unfortunately the wl command does not work with the wifi interface (s) of this specific router. Resolved by changing the "wl .." command in the phython script to "arp -a | grep br0 | awk '{print $ 4}'". It's working! (and fast detection).

Domoticz

Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router

Re: Python plugin: Presence detection from wireless router