Python plugin: Presence detection from wireless router

EscApe · Post by **EscApe** » Monday 27 March 2023 17:47

hestia wrote: ↑Monday 27 March 2023 17:24 +
I've given log in the post with the debug on
viewtopic.php?p=301063#p301063
If you need more log, could you give me what to do please.

A ran the ssh tracker with two Asus routers without any problems until little over a year ago. You could also try running it on only one or two routers for a little while. Just for diagnostics.
On the new env. (w the issue) there only 1 router

Perhaps, I could use only one router always, because in the GUI they all have the same client list

Hi @hestia,

That's why that extensive kind of log in that post is helpful to have with every try... (don't need one now)

Maybe we have a bit of a language barrier. What I understand from the log you are referring to was that there where three routers (Tracker configuration:wapsalon,wapchambre,wapstudio).... But "On the new env. (w the issue) there only 1 router".
There is some more information in this thread that seems conflicting to me but probably makes total sense to you. Like in the first messages you needed to restart domoticz and later it turns out you only needed to restrat the plugin. Completely normal to gain these kind of new insights while troubleshooting, but sometimes confusing when trying to assist remotely.

No matter what, we will keep trying

Did you see my previous message about Domoticz starting before the linux network interface is completely up? That is e very likely source for this kind of issue.

hestia · Post by **hestia** » Monday 27 March 2023 17:59

Like in the first messages you needed to restart domoticz and later it turns out you only needed to restrat the plugin. Completely normal to gain these kind of new insights while troubleshooting, but sometimes confusing when trying to assist remotely.

I was also a bit confuse about this also...
And when I've installed again domoticz and only the 2 plugins at stakes, I understand better.
In fact, as I remember after the first installation of the plugin, domoticz froze, so I had to stop an restart.
Now it's always the same issue, the error in the log

did you see my previous message about Domoticz starting before the linux network interface is completely up? That is e very likely source for this kind of issue.

Yes and my answer was the I restart only domoticz
I've just done a reboot of the server and it's the same as a restart of dz.

EscApe · Post by **EscApe** » Monday 27 March 2023 19:02

I have run out of ideas, so I will try and replicate your setup. Hopefully I can offer some new insights next weekend.

hestia · Post by **hestia** » Monday 27 March 2023 19:15

Thanks for your help!
Could you give me the command the plugin uses on the router to get the devices? So that I could run it to check if there is something on the router.

mojso · Post by **mojso** » Monday 27 March 2023 21:27

very good, works with dd-wrt

EscApe · Post by **EscApe** » Wednesday 29 March 2023 13:10

hestia wrote: ↑Monday 27 March 2023 19:15 Thanks for your help!
Could you give me the command the plugin uses on the router to get the devices? So that I could run it to check if there is something on the router.

I build a test environment using Debian Bullseye and python3.9 to try and replicate your issue. Configured three trackers all pointing at the same Asus router (ac68u), so if there ever was a reason for congestions I certainly created one there

.

Even in this setup I could not replicate your issue. Restarting Domoticz or restarting the plugin, it alle works just fine.

The testserver is in a Docker container, so that is one possible difference, but I don't think it is relevant to the issue. It would be if your problem only occurred when rebooting the host.

I did just pushed another update to GitHub. It wil not solve your issue, but the debug logging has been improved. Maybe that will bring us new insights.

To answer your other question: the command used on any router is in your debug log like:

Code: Select all

2023-03-21 19:43:43.897 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-21 19:43:43.897 /usr/sbin/wl -i eth2 assoclist

cleaned up:

Code: Select all

/usr/sbin/wl -i eth1 assoclist
/usr/sbin/wl -i eth2 assoclist

hestia · Post by **hestia** » Wednesday 29 March 2023 18:47

Thanks
My config is not so good as yours!

To install the update I did:

Code: Select all

/PROD_domoticz/plugins/iDetect $ git pull

and I've got

Spoiler: show: hint: Pulling without specifying how to reconcile divergent branches is
hint: discouraged. You can squelch this message by running one of the following
hint: commands sometime before your next pull:
hint:
hint: git config pull.rebase false # merge (the default strategy)
hint: git config pull.rebase true # rebase
hint: git config pull.ff only # fast-forward only
hint:
hint: You can replace "git config" with "git config --global" to set a default
hint: preference for all repositories. You can also pass --rebase, --no-rebase,
hint: or --ff-only on the command line to override the configured default per
hint: invocation.
remote: Enumerating objects: 44, done.
remote: Counting objects: 100% (44/44), done.
remote: Compressing objects: 100% (22/22), done.
remote: Total 34 (delta 25), reused 21 (delta 12), pack-reused 0
Unpacking objects: 100% (34/34), 5.34 KiB | 91.00 KiB/s, done.
From https://github.com/d-EScape/Domoticz_iDetect
be3ab23..80f015e master -> origin/master
Updating be3ab23..80f015e
Fast-forward
plugin.py | 75 +++++++++++++++++++++++++++++++++++++++------------------------------------
trackers/__init__.py | 16 +++++++++++++++-
trackers/http_omada.py | 2 +-
trackers/http_orbi.py | 2 +-
trackers/http_unifi.py | 2 +-
trackers/soap_netgear.py | 45 +++++++++++++++++++++++++++++++++++++++++++++
trackers/ssh_tracker.py | 2 +-
trackers/test_error_tracker.py | 17 +++++++++++++++++
trackers/tracker_base.py | 7 +++++--
trackers/unavailable_tracker.py | 26 ++++----------------------
10 files changed, 129 insertions(+), 65 deletions(-)
create mode 100755 trackers/soap_netgear.py
create mode 100755 trackers/test_error_tracker.py

and in domoticz

Spoiler: show: 2023-03-29 18:38:23.532 ePresence: ----> '_plugin' '<plugin.BasePlugin object at 0x6d991bb0>'
2023-03-29 18:38:23.532 ePresence: ----> 'data_helper' '<module 'helpers.data_helper' from '/home/pihestia/PROD_domoticz/plugins/iDetect/helpers/data_helper.py'>'
2023-03-29 18:38:23.529 Error: ePresence: Call to function 'onStart' failed, exception details:
2023-03-29 18:38:23.531 Error: ePresence: Traceback (most recent call last):
2023-03-29 18:38:23.531 Error: ePresence: File "/home/pihestia/PROD_domoticz/plugins/iDetect/plugin.py", line 428, in onStart
2023-03-29 18:38:23.531 Error: ePresence: _plugin.onStart()
2023-03-29 18:38:23.531 Error: ePresence: File "/home/pihestia/PROD_domoticz/plugins/iDetect/plugin.py", line 320, in onStart
2023-03-29 18:38:23.531 Error: ePresence: Domoticz.Debug('Configuring tracker:' + my_tracker)
2023-03-29 18:38:23.531 Error: ePresence: UnboundLocalError: local variable 'my_tracker' referenced before assignment

What did I do wrong?

EscApe · Post by **EscApe** » Wednesday 29 March 2023 18:59

hestia wrote: ↑Wednesday 29 March 2023 18:47 What did I do wrong?

Please include a full debug log, so I can see what the configuration is and how the plugin is using the configuration.

EDIT: Never mind.. was able to replicate this issue in the latest update on the test system (no problem on my production system). Will dive into it.

EscApe · Post by **EscApe** » Wednesday 29 March 2023 19:54

I pushed a new version that fixes the "local variable 'my_tracker' referenced before assignment" error. On my test system running Debian Bullseye and python3.9 it works, but crashes domoticz when restarting the plugin. I can stop the plugin without an error, but restart trows a segmentation fault.

No problem on my production python3.7 system. Will investigate further, but please do try the newer version on your test system and share the results.

hestia · Post by **hestia** » Wednesday 29 March 2023 21:33

new version installed (delete old plugin and new install)
Still the same issue
the log at the dz restart => KO

Spoiler: show: 023-03-29 21:18:44.458 Sunrise: 07:35:00 SunSet: 20:16:00
2023-03-29 21:18:44.458 Day length: 12:41:00 Sun at south: 13:56:00
2023-03-29 21:18:44.458 Civil twilight start: 07:03:00 Civil twilight end: 20:48:00
2023-03-29 21:18:44.458 Nautical twilight start: 06:25:00 Nautical twilight end: 21:26:00
2023-03-29 21:18:44.458 Astronomical twilight start: 05:46:00 Astronomical twilight end: 22:06:00
2023-03-29 21:18:44.532 Active notification Subsystems: email, http, telegram (3/13)
2023-03-29 21:18:44.418 Status: Domoticz V2023.1 (build 15098) (c)2012-2023 GizMoCuz
2023-03-29 21:18:44.418 Status: Build Hash: 867c4e8fa, Date: 2023-02-24 07:56:50
2023-03-29 21:18:44.418 Status: Startup Path: /home/pihestia/PROD_domoticz/
2023-03-29 21:18:44.524 Status: PluginSystem: Started, Python version '3.9.2', 3 plugin definitions loaded.
2023-03-29 21:18:44.537 Status: WebServer(HTTP) started on address: :: with port 8080
2023-03-29 21:18:46.621 zigbeeE: Worker thread started.
2023-03-29 21:18:46.621 ePresence: Worker thread started.
2023-03-29 21:18:46.621 Status: zigbeeE: Started.
2023-03-29 21:18:46.621 Status: zigbeeE: Entering work loop.
2023-03-29 21:18:46.621 Status: ePresence: Entering work loop.
2023-03-29 21:18:46.621 Status: ePresence: Started.
2023-03-29 21:18:46.621 Status: NotificationSystem: thread started...
2023-03-29 21:18:46.622 Status: EventSystem: reset all events...
...
2023-03-29 21:18:46.627 Status: EventSystem: reset all device statuses...
2023-03-29 21:18:46.929 Status: ePresence: Initialized version 2.3, author 'ESCape'
2023-03-29 21:18:46.959 Status: PluginSystem: 2 plugins started.
2023-03-29 21:18:48.036 Status: Python EventSystem: Initializing event module.
2023-03-29 21:18:48.036 Status: EventSystem: Started
2023-03-29 21:18:48.036 Status: EventSystem: Queue thread started...
2023-03-29 21:18:49.578 ePresence: Debug logging mask set to: PYTHON PLUGIN IMAGE DEVICE CONNECTION
2023-03-29 21:18:49.578 ePresence: Operation system is: linux
2023-03-29 21:18:50.055 ePresence: wapsalon ====> SSH returned (decoded):~eth1~eth2
2023-03-29 21:18:50.055 ePresence: wapsalon ====> SSH session took 139 milliseconds.
2023-03-29 21:18:50.058 ePresence: wapsalon Available interfaces for wl: ['eth1', 'eth2']
2023-03-29 21:18:50.058 ePresence: wapsalon Prepared to poll using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:18:50.058 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:18:50.058 exit
2023-03-29 21:18:50.058 ePresence: wapsalon tracker will autodetect ssh cli
2023-03-29 21:18:50.058 ePresence: wapsalon Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6ff9cd30>>
2023-03-29 21:18:50.058 ePresence: Tracker config:wapsalon, custom host:wapsalon, port:None, user:admin, type:default and options:{}
2023-03-29 21:18:50.058 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>}
2023-03-29 21:18:50.058 ePresence: Configuring tracker:wapchambre
2023-03-29 21:18:50.058 ePresence: options:
2023-03-29 21:18:50.058 ePresence: loaded module is:ssh_autodetect for type:default
2023-03-29 21:18:50.060 ePresence: wapchambre Tracker is of the ssh kind
2023-03-29 21:18:50.061 ePresence: wapchambre ====> SSH Fetching data using:
2023-03-29 21:18:50.061 export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH
2023-03-29 21:18:50.061 type wl
2023-03-29 21:18:50.061 type iwinfo
2023-03-29 21:18:50.061 type wlanconfig
2023-03-29 21:18:50.061 type wl_atheros
2023-03-29 21:18:50.061 type qcsapi_sockrpc
2023-03-29 21:18:50.061 type ip
2023-03-29 21:18:50.061 type brctl
2023-03-29 21:18:50.061 type arp
2023-03-29 21:18:50.061 [ -f /proc/net/arp ] && type cat
2023-03-29 21:18:50.061 echo 0
2023-03-29 21:18:50.061 exit
2023-03-29 21:18:50.061 ePresence: wapchambre ====> SSH not connected ... connecting
2023-03-29 21:18:50.061 ePresence: wapchambre ====> SSH start connect on port 22
2023-03-29 21:18:50.060 Status: ePresence: Starting address:wapchambre, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:18:50.288 Status: zigbeeE: Initialized version 6.3, author 'pipiche38'
2023-03-29 21:18:50.294 Status: zigbeeE: Zigbee for Domoticz plugin started!
2023-03-29 21:18:50.294 Status: zigbeeE: Python3 requires 3.8 or above and you are running 3.9
2023-03-29 21:18:50.294 Status: zigbeeE: Checking Python modules /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/requirements.txt
2023-03-29 21:18:51.703 zigbeeE: load PluginConf
2023-03-29 21:18:51.704 zigbeeE: Loading PluginConf - from Domoticz sqlite Db
2023-03-29 21:18:51.705 zigbeeE: /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/PluginConf-36.json timestamp is 1677528379.5616317
2023-03-29 21:18:51.705 zigbeeE: Dz PluginConf is older than Json Dz: 0 Json: 1677528379.5616317
2023-03-29 21:18:51.707 zigbeeE: Installing plugin custom page /home/pihestia/PROD_domoticz/www/templates/zigbeeE.html
2023-03-29 21:18:51.707 zigbeeE: Starting LoggingManagement thread
2023-03-29 21:18:51.711 zigbeeE: start_logging_thread
2023-03-29 21:18:51.712 zigbeeE: logging_thread - listening
2023-03-29 21:18:51.550 Status: zigbeeE: Checking Python modules /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/requirements.txt
2023-03-29 21:18:51.706 Status: zigbeeE: PluginAnalytics set to 1
2023-03-29 21:18:51.706 Status: zigbeeE: channel set to 15
2023-03-29 21:18:51.706 Status: zigbeeE: filename set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/PluginConf-36.json
2023-03-29 21:18:51.706 Status: zigbeeE: pluginHome set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/
2023-03-29 21:18:51.706 Status: zigbeeE: homedirectory set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/
2023-03-29 21:18:51.706 Status: zigbeeE: pluginData set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Data/
2023-03-29 21:18:51.706 Status: zigbeeE: pluginConfig set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/
2023-03-29 21:18:51.706 Status: zigbeeE: pluginOTAFirmware set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/OTAFirmware/
2023-03-29 21:18:51.707 Status: zigbeeE: pluginReports set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Reports/
2023-03-29 21:18:51.707 Status: zigbeeE: pluginWWW set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/www/
2023-03-29 21:18:51.707 Status: zigbeeE: pluginLogs set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Logs/
2023-03-29 21:18:51.707 Status: zigbeeE: ControllerInRawMode set to True
2023-03-29 21:18:51.712 Status: zigbeeE: Please watch plugin log into /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Logs//PluginZigbee_36.log
2023-03-29 21:18:51.729 Status: zigbeeE: Zigbee for Domoticz (z4d) plugin stable6-6.3.010 started
2023-03-29 21:18:51.741 Status: [web:8080] Incoming connection from: 127.0.0.1
2023-03-29 21:18:51.768 Status: zigbeeE: DeviceConf loaded - 17 confs loaded
2023-03-29 21:18:52.086 Status: zigbeeE: DeviceConf loaded - 424 confs loaded
2023-03-29 21:18:52.087 Status: zigbeeE: load ListOfDevice
2023-03-29 21:18:52.127 Status: zigbeeE: 4 Entries loaded from /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Data/DeviceList-36.txt
2023-03-29 21:18:52.143 Status: zigbeeE: Transport mode: ZigpyEZSP
2023-03-29 21:18:54.033 Status: zigbeeE: Start Zigpy Transport on EZSP
2023-03-29 21:18:54.040 Status: zigbeeE: ZigpyTransport: thread_processing_and_sending Thread start.
2023-03-29 21:18:54.041 Status: zigbeeE: Start Web Server connection
2023-03-29 21:18:54.091 Status: zigbeeE: Web backend for Web User Interface started on port: 9440
2023-03-29 21:18:54.092 Status: zigbeeE: Domoticz Widgets usage is at 2.7 % (248 units free)
2023-03-29 21:18:55.122 ePresence: wapchambre Could not retreive available commands
2023-03-29 21:18:55.122 ePresence: wapchambre tracker will autodetect ssh cli
2023-03-29 21:18:55.122 ePresence: wapchambre Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6ff9cd30>>
2023-03-29 21:18:55.122 ePresence: Tracker config:wapchambre, custom host:wapchambre, port:None, user:admin, type:default and options:{}
2023-03-29 21:18:55.122 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>, 'wapchambre': <trackers.ssh_autodetect.ssh_autodetect object at 0x68d424a8>}
2023-03-29 21:18:55.122 ePresence: Configuring tracker:wapstudio
2023-03-29 21:18:55.122 ePresence: options:
2023-03-29 21:18:55.122 ePresence: loaded module is:ssh_autodetect for type:default
2023-03-29 21:18:55.123 ePresence: wapstudio Tracker is of the ssh kind
2023-03-29 21:18:55.123 ePresence: wapstudio ====> SSH Fetching data using:
2023-03-29 21:18:55.123 export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH
2023-03-29 21:18:55.123 type wl
2023-03-29 21:18:55.123 type iwinfo
2023-03-29 21:18:55.123 type wlanconfig
2023-03-29 21:18:55.123 type wl_atheros
2023-03-29 21:18:55.123 type qcsapi_sockrpc
2023-03-29 21:18:55.123 type ip
2023-03-29 21:18:55.123 type brctl
2023-03-29 21:18:55.123 type arp
2023-03-29 21:18:55.123 [ -f /proc/net/arp ] && type cat
2023-03-29 21:18:55.123 echo 0
2023-03-29 21:18:55.123 exit
2023-03-29 21:18:55.123 ePresence: wapstudio ====> SSH not connected ... connecting
2023-03-29 21:18:55.123 ePresence: wapstudio ====> SSH start connect on port 22
2023-03-29 21:18:55.279 ePresence: wapstudio ====> SSH returned (decoded):wl is /usr/sbin/wl
2023-03-29 21:18:55.279 iwinfo: not found
2023-03-29 21:18:55.279 wlanconfig: not found
2023-03-29 21:18:55.279 wl_atheros: not found
2023-03-29 21:18:55.279 qcsapi_sockrpc: not found
2023-03-29 21:18:55.279 ip is /usr/sbin/ip
2023-03-29 21:18:55.279 brctl is /usr/sbin/brctl
2023-03-29 21:18:55.279 arp is /sbin/arp
2023-03-29 21:18:55.279 cat is /bin/cat
2023-03-29 21:18:55.279 0
2023-03-29 21:18:55.279
2023-03-29 21:18:55.279 ePresence: wapstudio ====> SSH session took 155 milliseconds.
2023-03-29 21:18:55.281 ePresence: Available commands on wapstudio:{'wl': '/usr/sbin/wl', 'ip': '/usr/sbin/ip', 'brctl': '/usr/sbin/brctl', 'arp': '/sbin/arp', 'cat': '/bin/cat'}
2023-03-29 21:18:55.281 ePresence: wapstudio ====> SSH Fetching data using:
2023-03-29 21:18:55.281 for iface in $(ifconfig | cut -d ' ' -f1| tr ':' '
2023-03-29 21:18:55.281 ' | grep -E '^eth|^wlan|^wl');do
2023-03-29 21:18:55.281 /usr/sbin/wl -i $iface assoclist > /dev/null 2>&1 && printf "~$iface"
2023-03-29 21:18:55.281 done
2023-03-29 21:18:55.281 exit
2023-03-29 21:18:55.373 ePresence: wapstudio ====> SSH returned (decoded):~eth1~eth2
2023-03-29 21:18:55.373 ePresence: wapstudio ====> SSH session took 91 milliseconds.
2023-03-29 21:18:55.376 ePresence: wapstudio Available interfaces for wl: ['eth1', 'eth2']
2023-03-29 21:18:55.376 ePresence: wapstudio Prepared to poll using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:18:55.376 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:18:55.376 exit
2023-03-29 21:18:55.376 ePresence: wapstudio tracker will autodetect ssh cli
2023-03-29 21:18:55.377 ePresence: wapstudio Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6ff9cd30>>
2023-03-29 21:18:55.377 ePresence: Tracker config:wapstudio, custom host:wapstudio, port:None, user:admin, type:default and options:{}
2023-03-29 21:18:55.377 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>, 'wapchambre': <trackers.ssh_autodetect.ssh_autodetect object at 0x68d424a8>, 'wapstudio': <trackers.ssh_autodetect.ssh_autodetect object at 0x67c3fd00>}
2023-03-29 21:18:55.377 ePresence: Heartbeat interval set to: 10.
2023-03-29 21:18:55.123 Status: ePresence: Starting address:wapstudio, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:18:55.243 Status: ePresence: wapstudio ====> SSH connection established
2023-03-29 21:18:55.122 Error: ePresence: wapchambre ====> SSH Could not connect (using password). Exception: No existing session
2023-03-29 21:18:56.080 ePresence: onHeartbeat called
2023-03-29 21:18:56.080 ePresence: 1 devices are present (excluding ignored devices)
...
2023-03-29 21:19:03.073 Status: zigbeeE: Request Disabling Accepting new Hardware
2023-03-29 21:19:04.602 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:19:04.602 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>>
2023-03-29 21:19:04.602 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:04.602 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:04.602 exit
2023-03-29 21:19:05.060 ePresence: wapchambre Not (yet) ready for polling
2023-03-29 21:19:05.060 ePresence: Using address:wapchambre, port:22, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:19:06.097 ePresence: onHeartbeat called
2023-03-29 21:19:06.097 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:08.092 Status: zigbeeE: coordinator set to Certification : 1/CE -> CE
2023-03-29 21:19:08.958 Status: zigbeeE: ota_scan_folder Following Firmware have been loaded
2023-03-29 21:19:08.959 Status: zigbeeE: Plugin with Zigpy, Coordinator Unknown Silicon Labs firmware UNK - 6.10.3.0 build 297 correctly initialized
2023-03-29 21:19:09.614 ePresence: wapsalon Could not be polled
2023-03-29 21:19:09.614 Status: ePresence: wapsalon ====> SSH resetting connection
2023-03-29 21:19:09.613 Error: ePresence: wapsalon ====> SSH failed with exception: Timeout opening channel.
2023-03-29 21:19:10.123 ePresence: wapstudio Timed poll starting like clockwork
2023-03-29 21:19:10.126 ePresence: wapstudio Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x67c3fd00>>
2023-03-29 21:19:10.126 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:10.126 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:10.126 exit
2023-03-29 21:19:13.095 zigbeeE: checkPluginVersion - Upgrade available: 6.3.011
2023-03-29 21:19:13.100 Status: zigbeeE: *** A recent plugin version (6.3.011) is waiting for you on gitHub. You are on (6.3.010) ***
2023-03-29 21:19:15.138 ePresence: wapstudio Could not be polled
2023-03-29 21:19:15.138 Status: ePresence: wapstudio ====> SSH resetting connection
2023-03-29 21:19:15.137 Error: ePresence: wapstudio ====> SSH failed with exception: Timeout opening channel.
2023-03-29 21:19:16.064 ePresence: onHeartbeat called
2023-03-29 21:19:16.065 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:20.062 ePresence: wapchambre Not (yet) ready for polling
2023-03-29 21:19:20.062 ePresence: Using address:wapchambre, port:22, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:19:24.616 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:19:24.616 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>>
2023-03-29 21:19:24.616 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:24.616 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:24.616 exit
2023-03-29 21:19:24.616 ePresence: wapsalon ====> SSH not connected ... connecting
2023-03-29 21:19:24.616 ePresence: wapsalon ====> SSH start connect on port 22
2023-03-29 21:19:24.774 ePresence: wapsalon ====> SSH returned (decoded):assoclist 00:0A:F5:44:C0:24
2023-03-29 21:19:24.774 assoclist 68:39:43:FA:F2:94
2023-03-29 21:19:24.774 assoclist C4:DD:57:00:D7:61
2023-03-29 21:19:24.774 assoclist E8:68:E7:C1:51:10
2023-03-29 21:19:24.774 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:19:24.774 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:19:24.774 assoclist 20:79:18:95:79:64
2023-03-29 21:19:24.774 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:19:24.774
2023-03-29 21:19:24.774 ePresence: wapsalon ====> SSH session took 158 milliseconds.
2023-03-29 21:19:24.775 ePresence: wapsalon Sent RAW:assoclist 00:0A:F5:44:C0:24
2023-03-29 21:19:24.775 assoclist 68:39:43:FA:F2:94
2023-03-29 21:19:24.775 assoclist C4:DD:57:00:D7:61
2023-03-29 21:19:24.775 assoclist E8:68:E7:C1:51:10
2023-03-29 21:19:24.775 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:19:24.775 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:19:24.775 assoclist 20:79:18:95:79:64
2023-03-29 21:19:24.775 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:19:24.775
2023-03-29 21:19:24.782 ePresence: Inbound data from: wapsalon containing ['00:0A:F5:44:C0:24', '68:39:43:FA:F2:94', 'C4:DD:57:00:D7:61', 'E8:68:E7:C1:51:10', 'AC:2B:6E:EC:12:D3', '9E:32:76:7C:AD:7B', '20:79:18:95:79:64', 'AC:CF:5C:16:7B:EE']
2023-03-29 21:19:24.782 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:24.748 Status: ePresence: wapsalon ====> SSH connection established
2023-03-29 21:19:26.083 ePresence: onHeartbeat called
2023-03-29 21:19:26.083 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:30.139 ePresence: wapstudio Timed poll starting like clockwork
2023-03-29 21:19:30.141 ePresence: wapstudio Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x67c3fd00>>
2023-03-29 21:19:30.141 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:30.141 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:30.141 exit
2023-03-29 21:19:30.141 ePresence: wapstudio ====> SSH not connected ... connecting
2023-03-29 21:19:30.142 ePresence: wapstudio ====> SSH start connect on port 22
2023-03-29 21:19:30.265 Status: ePresence: wapstudio ====> SSH connection established
2023-03-29 21:19:35.064 ePresence: wapchambre Not (yet) ready for polling
2023-03-29 21:19:35.064 ePresence: Using address:wapchambre, port:22, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:19:35.273 ePresence: wapstudio Could not be polled
2023-03-29 21:19:35.272 Status: ePresence: wapstudio ====> SSH resetting connection
2023-03-29 21:19:35.271 Error: ePresence: wapstudio ====> SSH failed with exception:
2023-03-29 21:19:36.103 ePresence: onHeartbeat called
2023-03-29 21:19:36.104 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:39.783 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:19:39.783 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>>
2023-03-29 21:19:39.784 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:39.784 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:39.784 exit
2023-03-29 21:19:44.797 ePresence: wapsalon Could not be polled
2023-03-29 21:19:44.797 Status: ePresence: wapsalon ====> SSH resetting connection
2023-03-29 21:19:44.796 Error: ePresence: wapsalon ====> SSH failed with exception: Timeout opening channel.
2023-03-29 21:19:46.072 ePresence: onHeartbeat called
2023-03-29 21:19:46.073 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:50.065 ePresence: wapchambre Not (yet) ready for polling
2023-03-29 21:19:50.065 ePresence: Using address:wapchambre, port:22, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:19:50.274 ePresence: wapstudio Timed poll starting like clockwork
2023-03-29 21:19:50.274 ePresence: wapstudio Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x67c3fd00>>
2023-03-29 21:19:50.274 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:50.274 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:50.274 exit
2023-03-29 21:19:50.274 ePresence: wapstudio ====> SSH not connected ... connecting
2023-03-29 21:19:50.274 ePresence: wapstudio ====> SSH start connect on port 22
2023-03-29 21:19:50.420 ePresence: wapstudio ====> SSH returned (decoded):assoclist 68:C6:3A:A5:F1:3C
2023-03-29 21:19:50.420 assoclist E8:68:E7:6E:72:49
2023-03-29 21:19:50.420
2023-03-29 21:19:50.420 ePresence: wapstudio ====> SSH session took 145 milliseconds.
2023-03-29 21:19:50.422 ePresence: wapstudio Sent RAW:assoclist 68:C6:3A:A5:F1:3C
2023-03-29 21:19:50.422 assoclist E8:68:E7:6E:72:49
2023-03-29 21:19:50.422
2023-03-29 21:19:50.422 ePresence: Inbound data from: wapstudio containing ['68:C6:3A:A5:F1:3C', 'E8:68:E7:6E:72:49']
2023-03-29 21:19:50.422 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:19:50.395 Status: ePresence: wapstudio ====> SSH connection established
2023-03-29 21:19:56.089 ePresence: onHeartbeat called
2023-03-29 21:19:56.090 ( ePresence - Pascal) Updating device from 1:'On' to have values 0:'Off'.
2023-03-29 21:19:56.132 ePresence: Changed state of ePresence - Pascal to Off
2023-03-29 21:19:56.132 ePresence: Pascal has not been seen for 31.307831seconds --> set as absent.
2023-03-29 21:19:56.132 ePresence: 0 devices are present (excluding ignored devices)
2023-03-29 21:19:56.132 ( ePresence - Anyone) Updating device from 1:'On' to have values 0:'Off'.
2023-03-29 21:19:56.183 ePresence: Changed state of ePresence - Anyone to Off
2023-03-29 21:19:59.798 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:19:59.798 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>>
2023-03-29 21:19:59.798 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:19:59.798 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:19:59.798 exit
2023-03-29 21:19:59.798 ePresence: wapsalon ====> SSH not connected ... connecting
2023-03-29 21:19:59.798 ePresence: wapsalon ====> SSH start connect on port 22
2023-03-29 21:19:59.967 ePresence: wapsalon ====> SSH returned (decoded):assoclist 00:0A:F5:44:C0:24
2023-03-29 21:19:59.967 assoclist 68:39:43:FA:F2:94
2023-03-29 21:19:59.967 assoclist C4:DD:57:00:D7:61
2023-03-29 21:19:59.967 assoclist E8:68:E7:C1:51:10
2023-03-29 21:19:59.967 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:19:59.967 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:19:59.967 assoclist 20:79:18:95:79:64
2023-03-29 21:19:59.967 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:19:59.967
2023-03-29 21:19:59.968 ePresence: wapsalon ====> SSH session took 169 milliseconds.
2023-03-29 21:19:59.968 ePresence: wapsalon Sent RAW:assoclist 00:0A:F5:44:C0:24
2023-03-29 21:19:59.968 assoclist 68:39:43:FA:F2:94
2023-03-29 21:19:59.968 assoclist C4:DD:57:00:D7:61
2023-03-29 21:19:59.968 assoclist E8:68:E7:C1:51:10
2023-03-29 21:19:59.968 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:19:59.968 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:19:59.968 assoclist 20:79:18:95:79:64
2023-03-29 21:19:59.968 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:19:59.968
2023-03-29 21:19:59.968 ePresence: Inbound data from: wapsalon containing ['00:0A:F5:44:C0:24', '68:39:43:FA:F2:94', 'C4:DD:57:00:D7:61', 'E8:68:E7:C1:51:10', 'AC:2B:6E:EC:12:D3', '9E:32:76:7C:AD:7B', '20:79:18:95:79:64', 'AC:CF:5C:16:7B:EE']
2023-03-29 21:19:59.968 ( ePresence - Pascal) Updating device from 0:'Off' to have values 1:'On'.
2023-03-29 21:19:59.937 Status: ePresence: wapsalon ====> SSH connection established
2023-03-29 21:20:00.044 ePresence: Changed state of ePresence - Anyone to On
2023-03-29 21:20:02.132 Status: dzVents: Info: Handling Domoticz custom event for: "RC_TO_ALERT"
2023-03-29 21:20:02.167 Status: EventSystem: Script event triggered: /home/pihestia/PROD_domoticz/dzVents/runtime/dzVents.lua
2023-03-29 21:20:05.066 ePresence: wapchambre Not (yet) ready for polling
2023-03-29 21:20:05.068 ePresence: Using address:wapchambre, port:22, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:20:05.424 ePresence: wapstudio Timed poll starting like clockwork
2023-03-29 21:20:05.426 ePresence: wapstudio Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x67c3fd00>>
2023-03-29 21:20:05.426 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:20:05.426 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:20:05.426 exit
2023-03-29 21:20:05.241 Status: dzVents: Info: Handling Domoticz custom event for: "RC_TO_ALERT"
2023-03-29 21:20:05.276 Status: EventSystem: Script event triggered: /home/pihestia/PROD_domoticz/dzVents/runtime/dzVents.lua
2023-03-29 21:20:06.102 ePresence: onHeartbeat called
2023-03-29 21:20:06.102 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:20:08.464 Status: dzVents: Info: Handling Domoticz custom event for: "RC_TO_ALERT"
2023-03-29 21:20:08.496 Status: EventSystem: Script event triggered: /home/pihestia/PROD_domoticz/dzVents/runtime/dzVents.lua
2023-03-29 21:20:10.440 ePresence: wapstudio Could not be polled
2023-03-29 21:20:10.439 Status: ePresence: wapstudio ====> SSH resetting connection
2023-03-29 21:20:10.439 Error: ePresence: wapstudio ====> SSH failed with exception: Timeout opening channel.
2023-03-29 21:20:11.245 Status: dzVents: Info: Handling Domoticz custom event for: "RC_TO_ALERT"
2023-03-29 21:20:11.265 Status: EventSystem: Script event triggered: /home/pihestia/PROD_domoticz/dzVents/runtime/dzVents.lua
2023-03-29 21:20:14.504 Status: dzVents: Info: Handling Domoticz custom event for: "RC_TO_ALERT"
2023-03-29 21:20:14.537 Status: EventSystem: Script event triggered: /home/pihestia/PROD_domoticz/dzVents/runtime/dzVents.lua
2023-03-29 21:20:15.045 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:20:15.045 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x68d42208>>
2023-03-29 21:20:15.045 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:20:15.045 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:20:15.045 exit

The log at the plugin disable / enable => OK

Spoiler: show: 2023-03-29 21:20:50.263 ePresence: Worker thread started.
2023-03-29 21:20:50.263 Status: ePresence: Entering work loop.
2023-03-29 21:20:50.263 Status: ePresence: Started.
2023-03-29 21:20:50.470 Status: ePresence: Initialized version 2.3, author 'ESCape'
2023-03-29 21:20:51.812 ePresence: Debug logging mask set to: PYTHON PLUGIN IMAGE DEVICE CONNECTION
2023-03-29 21:20:51.812 ePresence: Operation system is: linux
2023-03-29 21:20:51.832 ePresence: The OS user profile running domoticz is: root
2023-03-29 21:20:51.832 ePresence: Parsing user and optional keyfile from:admin
2023-03-29 21:20:51.832 ePresence: start get or create wireless device
2023-03-29 21:20:51.832 ePresence: Camille monitor tag_id:EA:36:A7:8C:C5:A7, domoticz unit:2
2023-03-29 21:20:51.833 ePresence: start get or create wireless device
2023-03-29 21:20:51.833 ePresence: Mathilde monitor tag_id:FE:B5:68:2D:0B:22, domoticz unit:3
2023-03-29 21:20:51.833 ePresence: start get or create wireless device
2023-03-29 21:20:51.833 ePresence: Pascal monitor tag_id:00:0A:F5:44:C0:24, domoticz unit:4
2023-03-29 21:20:51.833 ePresence: start get or create wireless device
2023-03-29 21:20:51.833 ePresence: Valérie monitor tag_id:5A:46:E2:13:C5:3C, domoticz unit:5
2023-03-29 21:20:51.833 ePresence: start get or create wireless device
2023-03-29 21:20:51.833 ePresence: Constance monitor tag_id:30:32:35:14:2F:70, domoticz unit:6
2023-03-29 21:20:51.833 ePresence: Monitoring {'EA:36:A7:8C:C5:A7': <plugin.tag_device object at 0x6b5edd60>, 'FE:B5:68:2D:0B:22': <plugin.tag_device object at 0x6ed7b1a8>, '00:0A:F5:44:C0:24': <plugin.tag_device object at 0x6b507cd0>, '5A:46:E2:13:C5:3C': <plugin.tag_device object at 0x6d94f6a0>, '30:32:35:14:2F:70': <plugin.tag_device object at 0x695b4a00>} for presence.
2023-03-29 21:20:51.833 ePresence: Tracker configuration:wapsalon,wapchambre,wapstudio
2023-03-29 21:20:51.833 ePresence: Configuring tracker:wapsalon
2023-03-29 21:20:51.833 ePresence: options:
2023-03-29 21:20:51.833 ePresence: loaded module is:ssh_autodetect for type:default
2023-03-29 21:20:51.835 ePresence: wapsalon Tracker is of the ssh kind
2023-03-29 21:20:51.835 ePresence: wapsalon ====> SSH Fetching data using:
2023-03-29 21:20:51.835 export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH
2023-03-29 21:20:51.835 type wl
2023-03-29 21:20:51.835 type iwinfo
2023-03-29 21:20:51.835 type wlanconfig
2023-03-29 21:20:51.835 type wl_atheros
2023-03-29 21:20:51.835 type qcsapi_sockrpc
2023-03-29 21:20:51.835 type ip
2023-03-29 21:20:51.835 type brctl
2023-03-29 21:20:51.835 type arp
2023-03-29 21:20:51.835 [ -f /proc/net/arp ] && type cat
2023-03-29 21:20:51.835 echo 0
2023-03-29 21:20:51.835 exit
2023-03-29 21:20:51.835 ePresence: wapsalon ====> SSH not connected ... connecting
2023-03-29 21:20:51.835 ePresence: wapsalon ====> SSH start connect on port 22
2023-03-29 21:20:51.989 ePresence: wapsalon ====> SSH returned (decoded):wl is /usr/sbin/wl
2023-03-29 21:20:51.989 iwinfo: not found
2023-03-29 21:20:51.989 wlanconfig: not found
2023-03-29 21:20:51.989 wl_atheros: not found
2023-03-29 21:20:51.989 qcsapi_sockrpc: not found
2023-03-29 21:20:51.989 ip is /usr/sbin/ip
2023-03-29 21:20:51.989 brctl is /usr/sbin/brctl
2023-03-29 21:20:51.989 arp is /sbin/arp
2023-03-29 21:20:51.989 cat is /bin/cat
2023-03-29 21:20:51.989 0
2023-03-29 21:20:51.989
2023-03-29 21:20:51.989 ePresence: wapsalon ====> SSH session took 154 milliseconds.
2023-03-29 21:20:51.989 ePresence: Available commands on wapsalon:{'wl': '/usr/sbin/wl', 'ip': '/usr/sbin/ip', 'brctl': '/usr/sbin/brctl', 'arp': '/sbin/arp', 'cat': '/bin/cat'}
2023-03-29 21:20:51.990 ePresence: wapsalon ====> SSH Fetching data using:
2023-03-29 21:20:51.990 for iface in $(ifconfig | cut -d ' ' -f1| tr ':' '
2023-03-29 21:20:51.990 ' | grep -E '^eth|^wlan|^wl');do
2023-03-29 21:20:51.990 /usr/sbin/wl -i $iface assoclist > /dev/null 2>&1 && printf "~$iface"
2023-03-29 21:20:51.990 done
2023-03-29 21:20:51.990 exit
2023-03-29 21:20:51.834 Status: ePresence: Starting address:wapsalon, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:20:51.956 Status: ePresence: wapsalon ====> SSH connection established
2023-03-29 21:20:52.076 ePresence: wapsalon ====> SSH returned (decoded):~eth1~eth2
2023-03-29 21:20:52.076 ePresence: wapsalon ====> SSH session took 86 milliseconds.
2023-03-29 21:20:52.077 ePresence: wapsalon Available interfaces for wl: ['eth1', 'eth2']
2023-03-29 21:20:52.077 ePresence: wapsalon Prepared to poll using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:20:52.077 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:20:52.077 exit
2023-03-29 21:20:52.077 ePresence: wapsalon tracker will autodetect ssh cli
2023-03-29 21:20:52.077 ePresence: wapsalon Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6edd7568>>
2023-03-29 21:20:52.077 ePresence: Tracker config:wapsalon, custom host:wapsalon, port:None, user:admin, type:default and options:{}
2023-03-29 21:20:52.077 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4a30>}
2023-03-29 21:20:52.077 ePresence: Configuring tracker:wapchambre
2023-03-29 21:20:52.077 ePresence: options:
2023-03-29 21:20:52.077 ePresence: loaded module is:ssh_autodetect for type:default
2023-03-29 21:20:52.078 ePresence: wapchambre Tracker is of the ssh kind
2023-03-29 21:20:52.078 ePresence: wapchambre ====> SSH Fetching data using:
2023-03-29 21:20:52.078 export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH
2023-03-29 21:20:52.078 type wl
2023-03-29 21:20:52.078 type iwinfo
2023-03-29 21:20:52.078 type wlanconfig
2023-03-29 21:20:52.078 type wl_atheros
2023-03-29 21:20:52.078 type qcsapi_sockrpc
2023-03-29 21:20:52.078 type ip
2023-03-29 21:20:52.078 type brctl
2023-03-29 21:20:52.078 type arp
2023-03-29 21:20:52.078 [ -f /proc/net/arp ] && type cat
2023-03-29 21:20:52.078 echo 0
2023-03-29 21:20:52.078 exit
2023-03-29 21:20:52.078 ePresence: wapchambre ====> SSH not connected ... connecting
2023-03-29 21:20:52.078 ePresence: wapchambre ====> SSH start connect on port 22
2023-03-29 21:20:52.352 ePresence: wapchambre ====> SSH returned (decoded):wl is /usr/sbin/wl
2023-03-29 21:20:52.352 iwinfo: not found
2023-03-29 21:20:52.352 wlanconfig: not found
2023-03-29 21:20:52.352 wl_atheros: not found
2023-03-29 21:20:52.352 qcsapi_sockrpc: not found
2023-03-29 21:20:52.352 ip is /usr/sbin/ip
2023-03-29 21:20:52.352 brctl is /usr/sbin/brctl
2023-03-29 21:20:52.352 arp is /sbin/arp
2023-03-29 21:20:52.352 cat is /bin/cat
2023-03-29 21:20:52.352 0
2023-03-29 21:20:52.352
2023-03-29 21:20:52.352 ePresence: wapchambre ====> SSH session took 273 milliseconds.
2023-03-29 21:20:52.353 ePresence: Available commands on wapchambre:{'wl': '/usr/sbin/wl', 'ip': '/usr/sbin/ip', 'brctl': '/usr/sbin/brctl', 'arp': '/sbin/arp', 'cat': '/bin/cat'}
2023-03-29 21:20:52.353 ePresence: wapchambre ====> SSH Fetching data using:
2023-03-29 21:20:52.353 for iface in $(ifconfig | cut -d ' ' -f1| tr ':' '
2023-03-29 21:20:52.353 ' | grep -E '^eth|^wlan|^wl');do
2023-03-29 21:20:52.353 /usr/sbin/wl -i $iface assoclist > /dev/null 2>&1 && printf "~$iface"
2023-03-29 21:20:52.353 done
2023-03-29 21:20:52.353 exit
2023-03-29 21:20:52.460 ePresence: wapchambre ====> SSH returned (decoded):~eth1~eth2~wl0.1
2023-03-29 21:20:52.460 ePresence: wapchambre ====> SSH session took 107 milliseconds.
2023-03-29 21:20:52.462 ePresence: wapchambre Available interfaces for wl: ['eth1', 'eth2', 'wl0.1']
2023-03-29 21:20:52.462 ePresence: wapchambre Prepared to poll using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:20:52.462 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:20:52.462 /usr/sbin/wl -i wl0.1 assoclist
2023-03-29 21:20:52.462 exit
2023-03-29 21:20:52.462 ePresence: wapchambre tracker will autodetect ssh cli
2023-03-29 21:20:52.462 ePresence: wapchambre Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6edd7568>>
2023-03-29 21:20:52.462 ePresence: Tracker config:wapchambre, custom host:wapchambre, port:None, user:admin, type:default and options:{}
2023-03-29 21:20:52.462 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4a30>, 'wapchambre': <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4d30>}
2023-03-29 21:20:52.462 ePresence: Configuring tracker:wapstudio
2023-03-29 21:20:52.462 ePresence: options:
2023-03-29 21:20:52.462 ePresence: loaded module is:ssh_autodetect for type:default
2023-03-29 21:20:52.463 ePresence: wapstudio Tracker is of the ssh kind
2023-03-29 21:20:52.463 ePresence: wapstudio ====> SSH Fetching data using:
2023-03-29 21:20:52.463 export PATH=/usr/sbin:/usr/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:$PATH
2023-03-29 21:20:52.463 type wl
2023-03-29 21:20:52.463 type iwinfo
2023-03-29 21:20:52.463 type wlanconfig
2023-03-29 21:20:52.463 type wl_atheros
2023-03-29 21:20:52.463 type qcsapi_sockrpc
2023-03-29 21:20:52.463 type ip
2023-03-29 21:20:52.463 type brctl
2023-03-29 21:20:52.463 type arp
2023-03-29 21:20:52.463 [ -f /proc/net/arp ] && type cat
2023-03-29 21:20:52.463 echo 0
2023-03-29 21:20:52.463 exit
2023-03-29 21:20:52.463 ePresence: wapstudio ====> SSH not connected ... connecting
2023-03-29 21:20:52.463 ePresence: wapstudio ====> SSH start connect on port 22
2023-03-29 21:20:52.617 ePresence: wapstudio ====> SSH returned (decoded):wl is /usr/sbin/wl
2023-03-29 21:20:52.617 iwinfo: not found
2023-03-29 21:20:52.617 wlanconfig: not found
2023-03-29 21:20:52.617 wl_atheros: not found
2023-03-29 21:20:52.617 qcsapi_sockrpc: not found
2023-03-29 21:20:52.617 ip is /usr/sbin/ip
2023-03-29 21:20:52.617 brctl is /usr/sbin/brctl
2023-03-29 21:20:52.617 arp is /sbin/arp
2023-03-29 21:20:52.617 cat is /bin/cat
2023-03-29 21:20:52.617 0
2023-03-29 21:20:52.617
2023-03-29 21:20:52.617 ePresence: wapstudio ====> SSH session took 153 milliseconds.
2023-03-29 21:20:52.619 ePresence: Available commands on wapstudio:{'wl': '/usr/sbin/wl', 'ip': '/usr/sbin/ip', 'brctl': '/usr/sbin/brctl', 'arp': '/sbin/arp', 'cat': '/bin/cat'}
2023-03-29 21:20:52.619 ePresence: wapstudio ====> SSH Fetching data using:
2023-03-29 21:20:52.619 for iface in $(ifconfig | cut -d ' ' -f1| tr ':' '
2023-03-29 21:20:52.619 ' | grep -E '^eth|^wlan|^wl');do
2023-03-29 21:20:52.619 /usr/sbin/wl -i $iface assoclist > /dev/null 2>&1 && printf "~$iface"
2023-03-29 21:20:52.619 done
2023-03-29 21:20:52.619 exit
2023-03-29 21:20:52.711 ePresence: wapstudio ====> SSH returned (decoded):~eth1~eth2
2023-03-29 21:20:52.711 ePresence: wapstudio ====> SSH session took 91 milliseconds.
2023-03-29 21:20:52.713 ePresence: wapstudio Available interfaces for wl: ['eth1', 'eth2']
2023-03-29 21:20:52.713 ePresence: wapstudio Prepared to poll using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:20:52.713 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:20:52.713 exit
2023-03-29 21:20:52.713 ePresence: wapstudio tracker will autodetect ssh cli
2023-03-29 21:20:52.713 ePresence: wapstudio Data will be received and interpreted by <bound method BasePlugin.onDataReceive of <plugin.BasePlugin object at 0x6edd7568>>
2023-03-29 21:20:52.713 ePresence: Tracker config:wapstudio, custom host:wapstudio, port:None, user:admin, type:default and options:{}
2023-03-29 21:20:52.713 ePresence: Trackers initialized as:{'wapsalon': <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4a30>, 'wapchambre': <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4d30>, 'wapstudio': <trackers.ssh_autodetect.ssh_autodetect object at 0x6947e6d0>}
2023-03-29 21:20:52.714 ePresence: Heartbeat interval set to: 10.
2023-03-29 21:20:52.078 Status: ePresence: Starting address:wapchambre, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:20:52.319 Status: ePresence: wapchambre ====> SSH connection established
2023-03-29 21:20:52.463 Status: ePresence: Starting address:wapstudio, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-03-29 21:20:52.585 Status: ePresence: wapstudio ====> SSH connection established
2023-03-29 21:21:00.078 ePresence: onHeartbeat called
2023-03-29 21:21:00.079 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:21:06.835 ePresence: wapsalon Timed poll starting like clockwork
2023-03-29 21:21:06.835 ePresence: wapsalon Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4a30>>
2023-03-29 21:21:06.835 ePresence: wapsalon ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:21:06.835 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:21:06.835 exit
2023-03-29 21:21:06.861 ePresence: wapsalon ====> SSH returned (decoded):assoclist 00:0A:F5:44:C0:24
2023-03-29 21:21:06.861 assoclist 68:39:43:FA:F2:94
2023-03-29 21:21:06.861 assoclist C4:DD:57:00:D7:61
2023-03-29 21:21:06.861 assoclist E8:68:E7:C1:51:10
2023-03-29 21:21:06.861 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:21:06.861 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:21:06.861 assoclist 20:79:18:95:79:64
2023-03-29 21:21:06.861 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:21:06.861
2023-03-29 21:21:06.861 ePresence: wapsalon ====> SSH session took 26 milliseconds.
2023-03-29 21:21:06.864 ePresence: wapsalon Sent RAW:assoclist 00:0A:F5:44:C0:24
2023-03-29 21:21:06.864 assoclist 68:39:43:FA:F2:94
2023-03-29 21:21:06.864 assoclist C4:DD:57:00:D7:61
2023-03-29 21:21:06.864 assoclist E8:68:E7:C1:51:10
2023-03-29 21:21:06.864 assoclist AC:2B:6E:EC:12:D3
2023-03-29 21:21:06.864 assoclist 9E:32:76:7C:AD:7B
2023-03-29 21:21:06.864 assoclist 20:79:18:95:79:64
2023-03-29 21:21:06.864 assoclist AC:CF:5C:16:7B:EE
2023-03-29 21:21:06.864
2023-03-29 21:21:06.872 ePresence: Inbound data from: wapsalon containing ['00:0A:F5:44:C0:24', '68:39:43:FA:F2:94', 'C4:DD:57:00:D7:61', 'E8:68:E7:C1:51:10', 'AC:2B:6E:EC:12:D3', '9E:32:76:7C:AD:7B', '20:79:18:95:79:64', 'AC:CF:5C:16:7B:EE']
2023-03-29 21:21:06.872 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:21:07.078 ePresence: wapchambre Timed poll starting like clockwork
2023-03-29 21:21:07.078 ePresence: wapchambre Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x695b4d30>>
2023-03-29 21:21:07.078 ePresence: wapchambre ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:21:07.078 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:21:07.078 /usr/sbin/wl -i wl0.1 assoclist
2023-03-29 21:21:07.078 exit
2023-03-29 21:21:07.110 ePresence: wapchambre ====> SSH returned (decoded):assoclist B8:27:EB:13:3A:55
2023-03-29 21:21:07.110 assoclist 18:26:49:11:BC:78
2023-03-29 21:21:07.110 assoclist B8:FF:61:AF:DD:5E
2023-03-29 21:21:07.110 assoclist B8:27:EB:C8:F0:50
2023-03-29 21:21:07.110
2023-03-29 21:21:07.110 ePresence: wapchambre ====> SSH session took 31 milliseconds.
2023-03-29 21:21:07.111 ePresence: wapchambre Sent RAW:assoclist B8:27:EB:13:3A:55
2023-03-29 21:21:07.111 assoclist 18:26:49:11:BC:78
2023-03-29 21:21:07.111 assoclist B8:FF:61:AF:DD:5E
2023-03-29 21:21:07.111 assoclist B8:27:EB:C8:F0:50
2023-03-29 21:21:07.111
2023-03-29 21:21:07.111 ePresence: Inbound data from: wapchambre containing ['B8:27:EB:13:3A:55', '18:26:49:11:BC:78', 'B8:FF:61:AF:DD:5E', 'B8:27:EB:C8:F0:50']
2023-03-29 21:21:07.111 ePresence: 1 devices are present (excluding ignored devices)
2023-03-29 21:21:07.463 ePresence: wapstudio Timed poll starting like clockwork
2023-03-29 21:21:07.463 ePresence: wapstudio Start poll and return results to <bound method tracker.receiver_callback of <trackers.ssh_autodetect.ssh_autodetect object at 0x6947e6d0>>
2023-03-29 21:21:07.463 ePresence: wapstudio ====> SSH Fetching data using: /usr/sbin/wl -i eth1 assoclist
2023-03-29 21:21:07.463 /usr/sbin/wl -i eth2 assoclist
2023-03-29 21:21:07.463 exit
2023-03-29 21:21:07.490 ePresence: wapstudio ====> SSH returned (decoded):assoclist 68:C6:3A:A5:F1:3C
2023-03-29 21:21:07.490 assoclist E8:68:E7:6E:72:49
2023-03-29 21:21:07.490
2023-03-29 21:21:07.490 ePresence: wapstudio ====> SSH session took 26 milliseconds.
2023-03-29 21:21:07.492 ePresence: wapstudio Sent RAW:assoclist 68:C6:3A:A5:F1:3C
2023-03-29 21:21:07.492 assoclist E8:68:E7:6E:72:49
2023-03-29 21:21:07.492
2023-03-29 21:21:07.493 ePresence: Inbound data from: wapstudio containing ['68:C6:3A:A5:F1:3C', 'E8:68:E7:6E:72:49']
2023-03-29 21:21:07.493 ePresence: 1 devices are present (excluding ignored devices)

EscApe · Post by **EscApe** » Thursday 30 March 2023 16:57

hestia wrote: ↑Wednesday 29 March 2023 21:33 new version installed (delete old plugin and new install)
Still the same issue

Much easier to read with complete logs. Thanks. There is a part missing from when it didn't work. Seems like you cut a lot above "ePresence: Initialized version 2.3, author 'ESCape'", but the log is not always in the correct order. Don't think I need it right now.

1. The log shows zigbeeE starting at the same time. So your test setup is not as clean as I thought. Can you try disabling zigbeeE and restarting domoticz?
Even if that is the problem the plugin should try to reconnect later on, so I will look into that.

2. How does domoticz respond when you restart the plugin on your python3.9 test system ('update' button in settings)?

hestia · Post by **hestia** » Thursday 30 March 2023 18:05

Much easier to read with complete logs. Thanks. There is a part missing from when it didn't work. Seems like you cut a lot above "ePresence: Initialized version 2.3, author 'ESCape'", but the log is not always in the correct order. Don't think I need it right now.

I did the log by copy/paste from the GUI and I removed duplicate lines, perhaps I've messed them.
I've configured syslog, for the next ones
You'll see the following in the full log

1. The log shows zigbeeE starting at the same time. So your test setup is not as clean as I thought. Can you try disabling zigbeeE and restarting domoticz?
Even if that is the problem the plugin should try to reconnect later on, so I will look into that.

Thu 30 Mar 17:48:36 CEST 2023
sudo service domoticz.sh restart

2. How does domoticz respond when you restart the plugin on your python3.9 test system ('update' button in settings)?

Thu 30 Mar 17:50:12 CEST 2023
disable + enable iDetect

+
Thu 30 Mar 17:51:45 CEST 2023
enable zigbee

Thu 30 Mar 17:53:25 CEST 2023
sudo service domoticz.sh restart

Thu 30 Mar 17:55:35 CEST 2023
sudo reboot

I'll give you the full log by MP in case of sensitive info

hestia · Post by **hestia** » Thursday 30 March 2023 18:29

not sure to understand if/how MP works... We'll see if you receive them or not! (stuck in outbox)

EscApe · Post by **EscApe** » Friday 31 March 2023 7:32

hestia wrote: ↑Thursday 30 March 2023 18:05 I'll give you the full log by MP in case of sensitive info

As far as I can tell from your log and the steps in your post you did not perform:

disable zigbeeE
(keep iDetect enabled)
restart Domoticz

Is that correct or did I overlook something?
zigbeeE or another python plugin could very well be blocking iDetect during startup.

Best to test on a clean system (so only domoticz and iDetect) until we know iDetect is working and then start adding other stuff step by step to identify the conflicting component(s).

hestia · Post by **hestia** » Friday 31 March 2023 8:47

As far as I can tell from your log and the steps in your post you did not perform:

disable zigbeeE
(keep iDetect enabled)
restart Domoticz

I'm not sure to understand what you mean.
Anyway I was in a rush yesterday and my info were not accurate
Regarding the sequence I gave yesterday, here are the lines

sudo service domoticz.sh restart

Code: Select all

30/03/2023	17:48:42	Information	local6	domoticz	"Domoticz is exiting...			"	1387
30/03/2023	17:48:44	Information	local6	domoticz	"Domoticz is starting up....			"	1342

disable + enable iDetect

Code: Select all

30/03/2023	17:50:14	Notice	local6	domoticz	" ePresence: Stop directive received.			"	1089
30/03/2023	17:50:23	Notice	local6	domoticz	" ePresence: Started.			"	1067

enable zigbee

Code: Select all

Notice	local6	domoticz	"zigbeeE: Started.			"	847

sudo service domoticz.sh restart

Code: Select all

Information	local6	domoticz	"Domoticz is exiting...			"	595
Information	local6	domoticz	"Domoticz stopped...			"	521
Information	daemon	domoticz.sh	"domoticz: Domoticz is starting up....			"	513

sudo reboot

Code: Select all

30/03/2023	17:55:42	Notice	authpriv	sudo	"pihestia : TTY=pts/0 	 PWD=/home/pihestia 	 USER=root 	 COMMAND=/usr/sbin/reboot"	180
30/03/2023	17:55:42	Information	daemon	systemd	"Condition check resulted in Turns off Raspberry Pi display backlight on shutdown/reboot being skipped.			"	132

For each sequence, you'll find the lines of log after in the file

I'll send you the log again with the line marked with yellow

zigbeeE or another python plugin could very well be blocking iDetect during startup.

I only have those 2 python plugins, so yes there is an issue when both are there

Best to test on a clean system (so only domoticz and iDetect) until we know iDetect is working and then start adding other stuff step by step to identify the conflicting component(s).

If I doesn't enable Zigbee, iDetect is working well, so I don't understand what do you mean exactly

EscApe · Post by **EscApe** » Friday 31 March 2023 12:44

hestia wrote: ↑Friday 31 March 2023 8:47 If I doesn't enable Zigbee, iDetect is working well, so I don't understand what do you mean exactly

You said earlier the error occurred on a newly installed test server. I (mistakenly) assumed you meant a clean system with only iDetect running.
I think Zigbee and iDetect are both very busy communicating at startup and this is causing the iDetect communication to fail.

For now the work-around is to (re)start iDetect a little while after zigbee is finished initializing.

Another option would be to use a different zigbee integration. I'm using zigbee2mtt using autodiscovery. It is also very busy at startup, but does not block iDetect. The plugin framework is a single threaded proces, so if any python plugin waits for something then al other plugins will also wait. Maybe increasing the iDetect timeouts (as described before) to a much higher value (like 30 seconds or higher) will help(?)

In the mean time I will see if I can improve the startup of iDetect to automatically retry in these kind of conditions. Maybe this weekend.

hestia · Post by **hestia** » Friday 31 March 2023 13:13

You said earlier the error occurred on a newly installed test server. I (mistakenly) assumed you meant a clean system with only iDetect running.

In fact this server should be the new production one, when it works... so I hope it's a clean install

I think Zigbee and iDetect are both very busy communicating at startup and this is causing the iDetect communication to fail.

So I'm understanding that my new server installation as no specific issue, am I right?

For now the work-around is to (re)start iDetect a little while after zigbee is finished initializing.

How to do this? I didn't have much success with a json script, too much info to give

Another option would be to use a different zigbee integration. I'm using zigbee2mtt using autodiscovery. It is also very busy at startup, but does not block iDetect

That's an option I'm thinking of, or write a dedicated script for the detection out of domoticz

In the mean time I will see if I can improve the startup of iDetect to automatically retry in these kind of conditions. Maybe this weekend

Thanks, I'm not in the rush as I've been stuck on this new env. for a long time... I could wait next week

EscApe · Post by **EscApe** » Friday 31 March 2023 21:06

hestia wrote: ↑Friday 31 March 2023 13:13 Thanks, I'm not in the rush as I've been stuck on this new env. for a long time... I could wait next week

Or it can be as early as tonight

You can pull a new version from GitHub. This version will retry the initialization a few times (not indefinitely) when needed. Hopefully that will solve your problem.

hestia · Post by **hestia** » Saturday 01 April 2023 10:01

Thanks for the new version
But, the error is still present.
The log at the restart of dz

Spoiler: show: 2023-04-01 09:55:32.741 Sunrise: 07:29:00 SunSet: 20:21:00
2023-04-01 09:55:32.741 Day length: 12:52:00 Sun at south: 13:55:00
2023-04-01 09:55:32.741 Civil twilight start: 06:57:00 Civil twilight end: 20:53:00
2023-04-01 09:55:32.741 Nautical twilight start: 06:19:00 Nautical twilight end: 21:31:00
2023-04-01 09:55:32.741 Astronomical twilight start: 05:38:00 Astronomical twilight end: 22:11:00
2023-04-01 09:55:32.828 Active notification Subsystems: email, http, telegram (3/13)
2023-04-01 09:55:32.864 Starting shared server on: :::6144
2023-04-01 09:55:32.698 Status: Domoticz V2023.1 (build 15098) (c)2012-2023 GizMoCuz
2023-04-01 09:55:32.700 Status: Build Hash: 867c4e8fa, Date: 2023-02-24 07:56:50
2023-04-01 09:55:32.700 Status: Startup Path: /home/pihestia/PROD_domoticz/
2023-04-01 09:55:32.820 Status: PluginSystem: Started, Python version '3.9.2', 3 plugin definitions loaded.
2023-04-01 09:55:32.834 Status: WebServer(HTTP) started on address: :: with port 8080
2023-04-01 09:55:32.855 Status: WebServer(SSL) started on address: :: with port 443
2023-04-01 09:55:32.863 Status: Camera: settings (re)loaded
2023-04-01 09:55:32.865 Status: TCPServer: shared server started...
2023-04-01 09:55:32.868 Status: RxQueue: queue worker started...
2023-04-01 09:55:34.889 zigbeeE: Worker thread started.
2023-04-01 09:55:34.890 ePresence: Worker thread started.
2023-04-01 09:55:34.889 Status: zigbeeE: Entering work loop.
2023-04-01 09:55:34.889 Status: zigbeeE: Started.
2023-04-01 09:55:34.890 Status: ePresence: Entering work loop.
2023-04-01 09:55:34.890 Status: ePresence: Started.
2023-04-01 09:55:34.890 Status: NotificationSystem: thread started...
2023-04-01 09:55:34.891 Status: EventSystem: reset all events...
2023-04-01 09:55:34.897 Status: dzVents: Write file: /home/pihestia/PROD_domoticz/scripts/dzVents/generated_scripts/Z_NotifEnabler.lua
2023-04-01 09:55:34.898 Status: dzVents: Write file: /home/pihestia/PROD_domoticz/scripts/dzVents/generated_scripts/global_data.lua
2023-04-01 09:55:34.899 Status: dzVents: Write file: /home/pihestia/PROD_domoticz/scripts/dzVents/generated_scripts/IT_rc2Alert.lua
2023-04-01 09:55:34.900 Status: dzVents: Write file: /home/pihestia/PROD_domoticz/scripts/dzVents/generated_scripts/IT_DBCheck.lua
2023-04-01 09:55:34.901 Status: EventSystem: reset all device statuses...
2023-04-01 09:55:35.203 Status: ePresence: Initialized version 2.4, author 'ESCape'
2023-04-01 09:55:35.244 Status: PluginSystem: 2 plugins started.
2023-04-01 09:55:36.379 Status: Python EventSystem: Initializing event module.
2023-04-01 09:55:36.380 Status: EventSystem: Started
2023-04-01 09:55:36.380 Status: EventSystem: Queue thread started...
2023-04-01 09:55:37.971 Status: ePresence: Starting address:wapsalon, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-04-01 09:55:38.097 Status: ePresence: wapsalon ====> SSH connection established
2023-04-01 09:55:38.378 Status: ePresence: wapsalon Tracker initialized
2023-04-01 09:55:38.381 Status: ePresence: Starting address:wapchambre, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-04-01 09:55:40.174 zigbeeE: load PluginConf
2023-04-01 09:55:40.176 zigbeeE: Loading PluginConf - from Domoticz sqlite Db
2023-04-01 09:55:40.177 zigbeeE: /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/PluginConf-36.json timestamp is 1677528379.5616317
2023-04-01 09:55:40.177 zigbeeE: Dz PluginConf is older than Json Dz: 0 Json: 1677528379.5616317
2023-04-01 09:55:40.180 zigbeeE: Installing plugin custom page /home/pihestia/PROD_domoticz/www/templates/zigbeeE.html
2023-04-01 09:55:40.180 zigbeeE: Starting LoggingManagement thread
2023-04-01 09:55:40.184 zigbeeE: start_logging_thread
2023-04-01 09:55:40.185 zigbeeE: logging_thread - listening
2023-04-01 09:55:40.022 Status: zigbeeE: Checking Python modules /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/requirements.txt
2023-04-01 09:55:40.178 Status: zigbeeE: PluginAnalytics set to 1
2023-04-01 09:55:40.179 Status: zigbeeE: channel set to 15
2023-04-01 09:55:40.179 Status: zigbeeE: filename set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/PluginConf-36.json
2023-04-01 09:55:40.179 Status: zigbeeE: pluginHome set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/
2023-04-01 09:55:40.179 Status: zigbeeE: homedirectory set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginData set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Data/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginConfig set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Conf/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginOTAFirmware set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/OTAFirmware/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginReports set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Reports/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginWWW set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/www/
2023-04-01 09:55:40.179 Status: zigbeeE: pluginLogs set to /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Logs/
2023-04-01 09:55:40.180 Status: zigbeeE: ControllerInRawMode set to True
2023-04-01 09:55:40.185 Status: zigbeeE: Please watch plugin log into /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Logs//PluginZigbee_36.log
2023-04-01 09:55:40.200 Status: zigbeeE: Zigbee for Domoticz (z4d) plugin stable6-6.3.010 started
2023-04-01 09:55:40.213 Status: [web:8080] Incoming connection from: 127.0.0.1
2023-04-01 09:55:40.236 Status: zigbeeE: DeviceConf loaded - 17 confs loaded
2023-04-01 09:55:40.573 Status: zigbeeE: DeviceConf loaded - 424 confs loaded
2023-04-01 09:55:40.574 Status: zigbeeE: load ListOfDevice
2023-04-01 09:55:40.618 Status: zigbeeE: 4 Entries loaded from /home/pihestia/PROD_domoticz/plugins/Domoticz-Zigbee/Data/DeviceList-36.txt
2023-04-01 09:55:40.634 Status: zigbeeE: Transport mode: ZigpyEZSP
2023-04-01 09:55:42.515 Status: zigbeeE: Start Zigpy Transport on EZSP
2023-04-01 09:55:42.522 Status: zigbeeE: ZigpyTransport: thread_processing_and_sending Thread start.
2023-04-01 09:55:42.524 Status: zigbeeE: Start Web Server connection
2023-04-01 09:55:42.575 Status: zigbeeE: Web backend for Web User Interface started on port: 9440
2023-04-01 09:55:42.577 Status: zigbeeE: Domoticz Widgets usage is at 2.7 % (248 units free)
2023-04-01 09:55:43.149 Status: zigbeeE: Started radio ezsp port: /dev/ttyUSB-ZIGBEE
2023-04-01 09:55:43.464 Error: ePresence: wapchambre ====> SSH Could not connect (using password). Exception: No existing session
2023-04-01 09:55:45.438 Status: zigbeeE: Number of devices recently active in Zigate = 0
2023-04-01 09:55:45.486 Status: zigbeeE: EZSP Radio manufacturer:
2023-04-01 09:55:45.487 Status: zigbeeE: EZSP Radio board name:
2023-04-01 09:55:45.494 Status: zigbeeE: EmberZNet version: 6.10.3.0 build 297
2023-04-01 09:55:45.502 Status: zigbeeE: Network settings
2023-04-01 09:55:45.506 Status: zigbeeE: Channel: 15
2023-04-01 09:55:45.507 Status: zigbeeE: PAN ID: 0x1D29
2023-04-01 09:55:45.509 Status: zigbeeE: Extended PAN ID: 23:85:bc:4f:7f:92:27:d8
2023-04-01 09:55:45.512 Status: zigbeeE: Device IEEE: e0:79:8d:ff:fe:74:19:50
2023-04-01 09:55:45.514 Status: zigbeeE: Device NWK: 0x0000
2023-04-01 09:55:45.532 Status: zigbeeE: Installer Version Number: 6.10.3.0 build 297
2023-04-01 09:55:45.538 Status: zigbeeE: Branch Version: ==> Unknown Silicon Labs <==
2023-04-01 09:55:45.550 Status: zigbeeE: Zigbee Coordinator ieee: e0798dfffe741950 , short addr: 0000
2023-04-01 09:55:45.551 Status: zigbeeE: Network state UP, PANID: 1d29 extPANID: 0x2385bc4f7f9227d8 Channel: 15
2023-04-01 09:55:45.523 Error: zigbeeE: Untested Zigbee adapater model, please report to the Zigbee for Domoticz team
2023-04-01 09:55:48.515 Status: ePresence: Starting address:wapstudio, port:None, user:admin, keyfile:, class:ssh_autodetect and poll interval:15
2023-04-01 09:55:48.511 Error: ePresence: wapchambre ====> SSH Could not connect (using password). Exception: No existing session
2023-04-01 09:55:51.111 Status: zigbeeE: Request Disabling Accepting new Hardware
2023-04-01 09:55:53.382 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:55:56.079 Status: zigbeeE: coordinator set to Certification : 1/CE -> CE
2023-04-01 09:55:56.768 Status: zigbeeE: ota_scan_folder Following Firmware have been loaded
2023-04-01 09:55:56.769 Status: zigbeeE: Plugin with Zigpy, Coordinator Unknown Silicon Labs firmware UNK - 6.10.3.0 build 297 correctly initialized
2023-04-01 09:55:57.988 ePresence: wapsalon Could not be polled
2023-04-01 09:55:57.988 Status: ePresence: wapsalon ====> SSH resetting connection
2023-04-01 09:55:57.987 Error: ePresence: wapsalon ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:56:01.113 zigbeeE: checkPluginVersion - Upgrade available: 6.3.011
2023-04-01 09:56:01.132 Status: zigbeeE: *** A recent plugin version (6.3.011) is waiting for you on gitHub. You are on (6.3.010) ***
2023-04-01 09:56:08.385 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:56:08.527 ePresence: wapstudio Could not be polled
2023-04-01 09:56:08.385 Status: ePresence: wapchambre tracker initialization (still) not completed after waiting at least 15 seconds. Retrying 6 more times
2023-04-01 09:56:08.526 Status: ePresence: wapstudio ====> SSH resetting connection
2023-04-01 09:56:08.526 Error: ePresence: wapstudio ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:56:13.116 ePresence: wapsalon Could not be polled
2023-04-01 09:56:13.115 Status: ePresence: wapsalon ====> SSH connection established
2023-04-01 09:56:13.585 Error: ePresence: wapchambre ====> SSH Could not connect (using password). Exception: No existing session
2023-04-01 09:56:23.667 ePresence: wapstudio Could not be polled
2023-04-01 09:56:23.666 Status: ePresence: wapstudio ====> SSH connection established
2023-04-01 09:56:28.587 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:56:33.130 ePresence: wapsalon Could not be polled
2023-04-01 09:56:33.130 Status: ePresence: wapsalon ====> SSH resetting connection
2023-04-01 09:56:33.128 Error: ePresence: wapsalon ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:56:43.588 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:56:43.681 ePresence: wapstudio Could not be polled
2023-04-01 09:56:43.588 Status: ePresence: wapchambre tracker initialization (still) not completed after waiting at least 30 seconds. Retrying 5 more times
2023-04-01 09:56:43.680 Status: ePresence: wapstudio ====> SSH resetting connection
2023-04-01 09:56:43.613 Error: ePresence: wapchambre ====> SSH Could not connect (using password). Exception: Error reading SSH protocol banner
2023-04-01 09:56:43.679 Error: ePresence: wapstudio ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:56:48.256 ePresence: wapsalon Could not be polled
2023-04-01 09:56:48.256 Status: ePresence: wapsalon ====> SSH connection established
2023-04-01 09:56:58.615 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:56:58.806 ePresence: wapstudio Could not be polled
2023-04-01 09:56:58.806 Status: ePresence: wapstudio ====> SSH connection established
2023-04-01 09:57:08.269 ePresence: wapsalon Could not be polled
2023-04-01 09:57:08.269 Status: ePresence: wapsalon ====> SSH resetting connection
2023-04-01 09:57:08.268 Error: ePresence: wapsalon ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:57:13.616 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:57:18.824 ePresence: wapstudio Could not be polled
2023-04-01 09:57:18.824 Status: ePresence: wapstudio ====> SSH resetting connection
2023-04-01 09:57:18.822 Error: ePresence: wapstudio ====> SSH failed with exception: Timeout opening channel.
2023-04-01 09:57:23.407 ePresence: wapsalon Could not be polled
2023-04-01 09:57:23.407 Status: ePresence: wapsalon ====> SSH connection established
2023-04-01 09:57:28.618 ePresence: wapchambre Not (yet) fully initialized for polling
2023-04-01 09:57:33.958 ePresence: wapstudio Could not be polled
2023-04-01 09:57:33.958 Status: ePresence: wapstudio ====> SSH connection established

EscApe · Post by **EscApe** » Saturday 01 April 2023 11:32

hestia wrote: ↑Saturday 01 April 2023 10:01 Thanks for the new version
But, the error is still present.
The log at the restart of dz

That was my last idea to at least circumvent an unexplained conflict between the plugins.
Like the previous logs, this log also shows iDetect starting like expected and then failing as soon as zigbee starts.

I don't know where else to look except at your specific setup. You could try earlier python versions. The plugin system has proven te be very sensitive to python upgrades. Even if 3.9 is not brand new, you can find other problems with it on the forum.

Maybe @pipiche can offer some insights? He is using iDetect and author of zigbee for Domoticz, but dit not report any problem like this. Maybe he is also running a earlier python version(?)

Sorry, I have nothing else to offer (for now)...

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

Who is online