search

tomaae / homeassistant-mikrotik_router

Mikrotik router integration for Home Assistant
Apache License 2.0
311 stars 55 forks source link

[Bug] Accounting is not working in 1.6 #88

Closed sshalyminov closed 3 years ago

sshalyminov commented 3 years ago

Accounting is not working after upgrade to 1.6. Actually were was other issues: for example, all device_trackers of network clients were replaced with binary_sensors and device_trackers of router ports were duplicated, but all of this not big issue. Biggest issue - accounting is not working anymore. Old devices marked as unavailable and this not changed by changing settings of integration and rebooting. Later I had removed integration completely and added back. New sensors for accounting were not created. Here are lines from log:

2021-01-15 21:38:12 ERROR (MainThread) [homeassistant.util.logging] Exception in update_controller when dispatching 'mikrotik_router-update-Mikrotik Router': () Traceback (most recent call last): File "/config/custom_components/mikrotik_router/sensor.py", line 210, in update_controller update_items( File "/config/custom_components/mikrotik_router/sensor.py", line 320, in update_items sensors[item_id].async_schedule_update_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 441, in async_schedule_update_ha_state self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 292, in async_write_ha_state raise NoEntitySpecifiedError( homeassistant.exceptions.NoEntitySpecifiedError: No entity id specified for entity ESP-10 WAN TX

2021-01-15 21:38:42 ERROR (MainThread) [homeassistant.util.logging] Exception in update_controller when dispatching 'mikrotik_router-update-Mikrotik Router': () Traceback (most recent call last): File "/config/custom_components/mikrotik_router/sensor.py", line 210, in update_controller update_items( File "/config/custom_components/mikrotik_router/sensor.py", line 320, in update_items sensors[item_id].async_schedule_update_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 441, in async_schedule_update_ha_state self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 292, in async_write_ha_state raise NoEntitySpecifiedError( homeassistant.exceptions.NoEntitySpecifiedError: No entity id specified for entity ESP-10 WAN TX

2021-01-15 21:39:08 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.mi_temp_box_5_temperature is taking over 10 seconds 2021-01-15 21:39:12 ERROR (MainThread) [homeassistant.util.logging] Exception in update_controller when dispatching 'mikrotik_router-update-Mikrotik Router': () Traceback (most recent call last): File "/config/custom_components/mikrotik_router/sensor.py", line 210, in update_controller update_items( File "/config/custom_components/mikrotik_router/sensor.py", line 320, in update_items sensors[item_id].async_schedule_update_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 441, in async_schedule_update_ha_state self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 292, in async_write_ha_state raise NoEntitySpecifiedError( homeassistant.exceptions.NoEntitySpecifiedError: No entity id specified for entity ESP-10 WAN TX

and repeated again and again. In this log ESP-10 is one of network clients.

Home Assistant version: 2021.1.2 (same issue was in 2021.1.1 before I had upgrade it) Mikrotik Router integration version: 1.6 Mikrotik Hardware: RouterBOARD 750G r3 RouterOS version: 6.48

tomaae commented 3 years ago

Device tracker is still scanner type, it was not replaced with binary sensor. Router ports were not duplicated, new ones were created, old ones should be marked as unavailable. You will have to delete old ones. You may find it easier to just remove the router and re-add it.

For accounting, I will need debugs to see whats going on. This could be a duplicate name.

sshalyminov commented 3 years ago

You may find it easier to just remove the router and re-add it.

Finally I did this as I mentioned in message.

For accounting, I will need debugs to see whats going on.

If I can do something for you to debug this - let me know.

sshalyminov commented 3 years ago

BTW I have lot of messages like this in log: 2021-01-16 06:02:41 ERROR (SyncWorker_13) [custom_components.mikrotik_router.mikrotikapi] Mikrotik 192.168.1.1 error while arp_ping : unknown 2021-01-16 06:02:41 WARNING (SyncWorker_4) [custom_components.mikrotik_router.mikrotikapi] Mikrotik Reconnected to 192.168.1.1 2021-01-16 06:02:41 ERROR (SyncWorker_4) [custom_components.mikrotik_router.mikrotikapi] Mikrotik 192.168.1.1 error while arp_ping : unknown 2021-01-16 06:02:41 WARNING (SyncWorker_22) [custom_components.mikrotik_router.mikrotikapi] Mikrotik Reconnected to 192.168.1.1 May be important.

sshalyminov commented 3 years ago

During HA restart also messages:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 316, in async_add_entities await asyncio.gather(*tasks) File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 384, in _async_add_entity device_info = entity.device_info File "/config/custom_components/mikrotik_router/sensor.py", line 531, in device_info if self._data["manufacturer"] != "": KeyError: 'manufacturer'

tomaae commented 3 years ago

arp ping is crashing? something really wrong is going on there. first, ensure that you have all required permissions for ha user on your mikrotik. next, try with device tracking disabled and see if you get any other issue.

https://github.com/tomaae/homeassistant-mikrotik_router#enabling-debug Debug will show your mac and ip addresses. in some cases even passwords (such as PPP users). check for what you dont want to show before posting it here.

sshalyminov commented 3 years ago

Ok, with debug enabled I see how it works. Actually nothing interesting except ARP ping.

First of all about user: I did not create new user for this and used root to check how it works, so permissions are not issue.

Logs. From HA start I see integration can't add sensors:

2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface ether1) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface ether2) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface ether3) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface ether4) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface ether5) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface l2tp-beeline) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (interface pppoe-domru) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (script one_beep) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (script full_backup) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (script auto_full_restore) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (script full_restore) 2021-01-16 16:12:02 DEBUG (MainThread) [custom_components.mikrotik_router.switch] New switch Mikrotik Router (script Check for software updates) 2021-01-16 16:12:02 ERROR (MainThread) [homeassistant.components.sensor] Error adding entities for domain sensor with platform mikrotik_router Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 316, in async_add_entities await asyncio.gather(tasks) File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 384, in _async_add_entity device_info = entity.device_info File "/config/custom_components/mikrotik_router/sensor.py", line 531, in device_info if self._data["manufacturer"] != "": KeyError: 'manufacturer' 2021-01-16 16:12:02 ERROR (MainThread) [homeassistant.components.sensor] Error while setting up mikrotik_router platform for sensor Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 207, in _async_setup_platform await asyncio.gather(pending) File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 316, in async_add_entities await asyncio.gather(*tasks) File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 384, in _async_add_entity device_info = entity.device_info File "/config/custom_components/mikrotik_router/sensor.py", line 531, in device_info if self._data["manufacturer"] != "": KeyError: 'manufacturer' 2021-01-16 16:12:17 DEBUG (SyncWorker_16) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:17 DEBUG (SyncWorker_16) [custom_components.mikrotik_router.mikrotikapi] Ping host success: 192.168.2.108 2021-01-16 16:12:17 DEBUG (SyncWorker_2) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:17 DEBUG (SyncWorker_2) [custom_components.mikrotik_router.mikrotikapi] Ping host success: 192.168.2.103 2021-01-16 16:12:17 DEBUG (SyncWorker_23) [custom_components.mikrotik_router.mikrotikapi] API query: /ping

Looks like it can't add accounting sensors - all rest sensors are good and I have issues only with those sensors :)

Next lines shows problem with ARP ping:

2021-01-16 16:12:18 DEBUG (SyncWorker_5) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:18 DEBUG (SyncWorker_5) [custom_components.mikrotik_router.mikrotikapi] Ping host success: 192.168.1.19 2021-01-16 16:12:18 DEBUG (SyncWorker_21) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:18 DEBUG (SyncWorker_21) [custom_components.mikrotik_router.mikrotikapi] Ping host failure: 192.168.1.21 2021-01-16 16:12:18 DEBUG (SyncWorker_10) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:19 DEBUG (SyncWorker_10) [custom_components.mikrotik_router.mikrotikapi] Ping host failure: 192.168.1.106 2021-01-16 16:12:19 DEBUG (SyncWorker_26) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:19 DEBUG (SyncWorker_26) [custom_components.mikrotik_router.mikrotikapi] Ping host failure: 192.168.1.113 2021-01-16 16:12:19 DEBUG (SyncWorker_9) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:19 ERROR (SyncWorker_9) [custom_components.mikrotik_router.mikrotikapi] Mikrotik 192.168.1.1 error while arp_ping : unknown 2021-01-16 16:12:19 WARNING (SyncWorker_0) [custom_components.mikrotik_router.mikrotikapi] Mikrotik Reconnected to 192.168.1.1 2021-01-16 16:12:19 DEBUG (SyncWorker_0) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:19 DEBUG (SyncWorker_0) [custom_components.mikrotik_router.mikrotikapi] Ping host success: 192.168.1.202 2021-01-16 16:12:19 DEBUG (SyncWorker_29) [custom_components.mikrotik_router.mikrotikapi] API query: /ping 2021-01-16 16:12:20 DEBUG (SyncWorker_29) [custom_components.mikrotik_router.mikrotikapi] Ping host failure: 192.168.2.50 2021-01-16 16:12:20 DEBUG (SyncWorker_18) [custom_components.mikrotik_router.mikrotikapi] API query: /ping

It can't ping itself - 192.168.1.1 is IP of router. And yes, I have it in DNS entries (2 entries in different zones)

Next periodically integration requests info from router. Everything is requested correctly, I see replies and lists. Later it tries to update sensors and all sensors are updated successfully until accounting:

2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-environment-defconfMode 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-system_temperature 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-system_uptime 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-system_cpu-load 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-system_memory-usage 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-system_hdd-usage 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-ether1 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-ether2 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-ether3 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-ether4 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-ether5 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-l2tp-beeline 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_tx-pppoe-domru 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-ether1 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-ether2 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-ether3 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-ether4 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-ether5 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-l2tp-beeline 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.sensor] Updating sensor Mikrotik Router-traffic_rx-pppoe-domru 2021-01-16 16:14:02 ERROR (MainThread) [homeassistant.util.logging] Exception in update_controller when dispatching 'mikrotik_router-update-Mikrotik Router': () Traceback (most recent call last): File "/config/custom_components/mikrotik_router/sensor.py", line 210, in update_controller update_items( File "/config/custom_components/mikrotik_router/sensor.py", line 320, in update_items sensors[item_id].async_schedule_update_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 441, in async_schedule_update_ha_state self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 292, in async_write_ha_state raise NoEntitySpecifiedError( homeassistant.exceptions.NoEntitySpecifiedError: No entity id specified for entity ESP-10 WAN TX

2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-ether1 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-ether2 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-ether3 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-ether4 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-ether5 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-l2tp-beeline 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-interface-pppoe-domru 2021-01-16 16:14:02 DEBUG (MainThread) [custom_components.mikrotik_router.binary_sensor] Updating binary_sensor Mikrotik Router-system_fwupdate

Looks like sensors were not created during startup (I had quoted errors) and currently can't update.

tomaae commented 3 years ago

I will need full debug to see responses on api calls. This issue needs to be solved first, as it will most likely lead to the root cause:

2021-01-16 16:12:02 ERROR (MainThread) [homeassistant.components.sensor] Error adding entities for domain sensor with platform mikrotik_router
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 316, in async_add_entities
await asyncio.gather(*tasks)
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 384, in _async_add_entity
device_info = entity.device_info
File "/config/custom_components/mikrotik_router/sensor.py", line 531, in device_info
if self._data["manufacturer"] != "":
KeyError: 'manufacturer'

There is a device without manufacturer field in the loop, which should not happen.

2021-01-16 16:12:19 ERROR (SyncWorker_9) [custom_components.mikrotik_router.mikrotikapi] Mikrotik 192.168.1.1 error while arp_ping : unknown

This is most likely due to empty IP field. I assume related to an error above.

sshalyminov commented 3 years ago

home-assistant.mikrotik.log

Check this.

tomaae commented 3 years ago

Update integration to master and run debugs again. I have added additional debug points for both errors.

sshalyminov commented 3 years ago

Sorry for delay, was busy with other things. Updated from master, check log attached home-assistant.log

tomaae commented 3 years ago

No problem, take your time :) I have added workaround for one those issues. I would not call it a fix, since it should work this way. Lets see if it goes through and we will know more.

As for ping crashing, it is caused by following:

2021-01-19 17:04:49 DEBUG (MainThread) [custom_components.mikrotik_router.mikrotik_controller] Ping host: F8:28:19:93:44:2D (192.168.1.19)
2021-01-19 17:04:49 DEBUG (MainThread) [custom_components.mikrotik_router.mikrotik_controller] Ping host: E0:62:67:32:BA:30 (192.168.1.21)
2021-01-19 17:04:53 DEBUG (MainThread) [custom_components.mikrotik_router.mikrotik_controller] Ping host: E8:D0:FC:D9:B1:79 (192.168.1.22)
2021-01-19 17:04:55 DEBUG (MainThread) [custom_components.mikrotik_router.mikrotik_controller] Ping host: 04:D4:C4:52:59:9F (192.168.1.24)

Can you test ping locally using platform tools and see the result? I use 100ms ping

sshalyminov commented 3 years ago

Can you test ping locally using platform tools and see the result? I use 100ms ping

Sorry for noob question, but can you please explain what to do exactly? :)

sshalyminov commented 3 years ago

I see accounting sensors and data now after update. Excellent, thank you!

tomaae commented 3 years ago

Can you test ping locally using platform tools and see the result? I use 100ms ping

Sorry for noob question, but can you please explain what to do exactly? :)

for example: ping -w 100 192.168.1.19

sshalyminov commented 3 years ago

19 and 21 are offline now and "Request timeout" Rest two:

C:>ping -w 100 192.168.1.22

Pinging 192.168.1.22 with 32 bytes of data: Reply from 192.168.1.22: bytes=32 time=5ms TTL=128 Reply from 192.168.1.22: bytes=32 time=179ms TTL=128 Reply from 192.168.1.22: bytes=32 time=2ms TTL=128 Reply from 192.168.1.22: bytes=32 time=3ms TTL=128

Ping statistics for 192.168.1.22: Packets: Sent = 4, Received = 4, Lost = 0 (0% loss), Approximate round trip times in milli-seconds: Minimum = 2ms, Maximum = 179ms, Average = 47ms

C:>ping -w 100 192.168.1.24

Pinging 192.168.1.24 with 32 bytes of data: Reply from 192.168.1.24: bytes=32 time<1ms TTL=128 Reply from 192.168.1.24: bytes=32 time=15ms TTL=128 Reply from 192.168.1.24: bytes=32 time<1ms TTL=128 Reply from 192.168.1.24: bytes=32 time<1ms TTL=128

Ping statistics for 192.168.1.24: Packets: Sent = 4, Received = 4, Lost = 0 (0% loss), Approximate round trip times in milli-seconds: Minimum = 0ms, Maximum = 15ms, Average = 3ms

sshalyminov commented 3 years ago

While I wrote previous comment, 22 goes offline too :) 24 from router:

[root@router] > ping 192.168.1.24 SEQ HOST SIZE TTL TIME STATUS
0 192.168.1.24 56 128 0ms
1 192.168.1.24 56 128 0ms
2 192.168.1.24 56 128 0ms
3 192.168.1.24 56 128 1ms
4 192.168.1.24 56 128 0ms
5 192.168.1.24 56 128 0ms
6 192.168.1.24 56 128 0ms
sent=7 received=7 packet-loss=0% min-rtt=0ms avg-rtt=0ms max-rtt=1ms

tomaae commented 3 years ago

offline is fine. I have no idea why it actually crashes tho.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.