Device marked as away while it is not

SaturnusDJ commented 3 years ago

Okay here is a test case, zoomed in at one device. Sorry, I cannot run HA with only nmap_device. If this is absolutely necessary then I might try a second instance tomorrow.

Problem: Device being marked as away while it is not. This is a cabled desktop pc without connection problems. I tried a lot of config options like -F, different or nost host timeout, no timeout, consider_home of 300, interval_seconds of 90, etc.

Config:

  - platform: nmap_tracker
    hosts:
     - 192.168.1.3
    consider_home: 180
    timeout: 60
    interval_seconds: 120
    scan_options: "--host-timeout 2s"
    debug_log_level: 5

HA log:

Restarting Home Assistant
2021-10-20 01:00:19 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration nmap_tracker which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2021-10-20 01:00:29 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.nmap_tracker
2021-10-20 01:00:29 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.ping
2021-10-20 01:00:29 DEBUG (SyncWorker_5) [custom_components.nmap_tracker.device_tracker] Scanner initialized
2021-10-20 01:00:30 DEBUG (SyncWorker_0) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:00:30 DEBUG (SyncWorker_0) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_0] initialized for ['192.168.1.3']
2021-10-20 01:00:30 DEBUG (Thread-5) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-5
2021-10-20 01:00:30 DEBUG (SyncWorker_0) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = []
2021-10-20 01:00:32 DEBUG (Thread-5) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s 192.168.1.3
2021-10-20 01:00:32 DEBUG (Thread-5) [custom_components.nmap_tracker.device_tracker] Processing 192.168.1.3 up
2021-10-20 01:02:30 DEBUG (SyncWorker_4) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:02:30 DEBUG (SyncWorker_4) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_4] initialized for ['192.168.1.3']
2021-10-20 01:02:30 DEBUG (Thread-6) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-6
2021-10-20 01:02:30 DEBUG (SyncWorker_4) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = [Device(mac='11:22:33:44:55:66', name='', ip='192.168.1.3', last_update=datetime.datetime(2021, 10, 20, 1, 0, 32, 922187, tzinfo=zoneinfo.ZoneInfo(key='Europe/Amsterdam')), reason='arp-response')]
2021-10-20 01:02:30 DEBUG (SyncWorker_0) [custom_components.nmap_tracker.device_tracker] get_device_name (mac) for 11:22:33:44:55:66 = 11:22:33:44:55:66
2021-10-20 01:02:30 DEBUG (Thread-6) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s --exclude 192.168.1.3 192.168.1.3
2021-10-20 01:04:30 DEBUG (SyncWorker_3) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:04:30 DEBUG (SyncWorker_3) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_3] initialized for ['192.168.1.3']
2021-10-20 01:04:30 DEBUG (Thread-7) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-7
2021-10-20 01:04:30 DEBUG (SyncWorker_3) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = []
2021-10-20 01:04:32 DEBUG (Thread-7) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s 192.168.1.3
2021-10-20 01:04:32 DEBUG (Thread-7) [custom_components.nmap_tracker.device_tracker] Processing 192.168.1.3 up
2021-10-20 01:06:30 DEBUG (SyncWorker_1) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:06:30 DEBUG (SyncWorker_1) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_1] initialized for ['192.168.1.3']
2021-10-20 01:06:30 DEBUG (Thread-8) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-8
2021-10-20 01:06:30 DEBUG (SyncWorker_1) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = [Device(mac='11:22:33:44:55:66', name='', ip='192.168.1.3', last_update=datetime.datetime(2021, 10, 20, 1, 4, 32, 501180, tzinfo=zoneinfo.ZoneInfo(key='Europe/Amsterdam')), reason='arp-response')]
2021-10-20 01:06:30 DEBUG (Thread-8) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s --exclude 192.168.1.3 192.168.1.3
2021-10-20 01:08:30 DEBUG (SyncWorker_2) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:08:30 DEBUG (SyncWorker_2) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_2] initialized for ['192.168.1.3']
2021-10-20 01:08:30 DEBUG (Thread-9) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-9
2021-10-20 01:08:30 DEBUG (SyncWorker_2) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = []
2021-10-20 01:08:32 DEBUG (Thread-9) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s 192.168.1.3
2021-10-20 01:08:32 DEBUG (Thread-9) [custom_components.nmap_tracker.device_tracker] Processing 192.168.1.3 up
2021-10-20 01:10:30 DEBUG (SyncWorker_5) [custom_components.nmap_tracker.device_tracker] Nmap host list: 192.168.1.3
2021-10-20 01:10:30 DEBUG (SyncWorker_5) [custom_components.nmap_tracker.device_tracker] Processor [SyncWorker_5] initialized for ['192.168.1.3']
2021-10-20 01:10:30 DEBUG (Thread-10) [custom_components.nmap_tracker.device_tracker] Nmap Processor thread started: Thread-10
2021-10-20 01:10:30 DEBUG (SyncWorker_5) [custom_components.nmap_tracker.device_tracker] Nmap last results for 192.168.1.3 = [Device(mac='11:22:33:44:55:66', name='', ip='192.168.1.3', last_update=datetime.datetime(2021, 10, 20, 1, 8, 32, 529465, tzinfo=zoneinfo.ZoneInfo(key='Europe/Amsterdam')), reason='arp-response')]
2021-10-20 01:10:30 DEBUG (Thread-10) [custom_components.nmap_tracker.device_tracker] Nmap Command: nmap -oX - --host-timeout 2s --exclude 192.168.1.3 192.168.1.3

State of 192.168.1.3 in HA: State2 Note here that from 00:56:48 - 01:02:30 the state was away, despite the text not mentioning this.

Manual nmap in exact same environment:

bash-5.1# nmap -oX - --host-timeout 2s 192.168.1.3
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE nmaprun>
<?xml-stylesheet href="file:///usr/bin/../share/nmap/nmap.xsl" type="text/xsl"?>
<!-- Nmap 7.91 scan initiated Wed Oct 20 01:22:46 2021 as: nmap -oX - -&#45;host-timeout 2s 192.168.1.3 -->
<nmaprun scanner="nmap" args="nmap -oX - -&#45;host-timeout 2s 192.168.1.3" start="1634685766" startstr="Wed Oct 20 01:22:46 2021" version="7.91" xmloutputversion="1.05">
<scaninfo type="syn" protocol="tcp" numservices="1000" services="MANY PORTS HERE; REMOVED"/>
<verbose level="0"/>
<debugging level="0"/>
<hosthint><status state="up" reason="arp-response" reason_ttl="0"/>
<address addr="192.168.1.3" addrtype="ipv4"/>
<address addr="11:22:33:44:55:66" addrtype="mac" vendor="Asustek Computer"/>
<hostnames>
</hostnames>
</hosthint>
<host starttime="1634685766" endtime="1634685768"><status state="up" reason="arp-response" reason_ttl="0"/>
<address addr="192.168.1.3" addrtype="ipv4"/>
<address addr="11:22:33:44:55:66" addrtype="mac" vendor="Asustek Computer"/>
<hostnames>
</hostnames>
</host>
<runstats><finished time="1634685768" timestr="Wed Oct 20 01:22:48 2021" summary="Nmap done at Wed Oct 20 01:22:48 2021; 1 IP address (1 host up) scanned in 2.34 seconds" elapsed="2.34" exit="success"/><hosts up="1" down="0" total="1"/>
</runstats>
</nmaprun>

Host not excluded as sometimes happens in the HA setup.

rocket4321 commented 3 years ago

I don't see instances of the host being away in the debug log. Please provide an instance where this occurs.
The request to run only nmap is to mitigate server process overloading. Without this, there is not much that can be done for intermittent issues. For example, if the the home assistant cpu becomes overwhelmed, it's very possible a device may get marked as not present intermittently.

SaturnusDJ commented 3 years ago

I tried in 2 new/different environments.

New docker container with a stripped down config. CPU load is stable at 25% and not peaking higher than 50%.
VM on powerful Windows pc running Docker and HA. Bridged connection to the same network.

The outcome is exactly the same. The logs are the same. All the same as above.

Used configuration.yaml:

logger:
  default: warn
  logs:
    homeassistant.components.device_tracker: debug
    custom_components.nmap_tracker: debug

device_tracker:
  - platform: nmap_tracker
    hosts:
     - 192.168.1.3
    consider_home: 180
    timeout: 60
    interval_seconds: 120
    scan_options: "--host-timeout 2s"
    debug_log_level: 5

http:
  server_port: 8123

recorder:
history:
logbook:

So the logs should say the pc is down? I only see 'Processing 192.168.1.3 up' messages, nevertheless HA (?) does mark it as away from time to time.

SaturnusDJ commented 3 years ago

Any idea?

rocket4321 commented 3 years ago

Increase consider_home
Decease interval_seconds
Increase timeout
Test with alternative router and/or switch
If only occurs with single device, device is likely cause. Remove/replace device
Move device to wired if wireless
Confirm HA is triggering events based on change in binary_sensor status change, and not that this is a recorder issue
You don't have exclude_active - and there is quite a bit of details on how that helps.

SaturnusDJ commented 3 years ago

Thanks. The last thing you mention seems to help. Stupid of me, I should have read the readme better, sorry.

I ran into another thing:

    exclude:
    - 192.168.1.2
    - 192.168.1.4

This and many variant (no dashes, different indent, comma and/or space separated instead of list) somehow end up in the ip addresses being put at the very end of the nmap command with only the first ip addresses put after the --exclude flag. Not sure if that is how it is expected.

But using

scan_options: "--exclude 192.168.1.2,192.168.1.4"

works fine.

rocket4321 / nmap_tracker

Device marked as away while it is not #4