HASS.Agent icon indicating copy to clipboard operation
HASS.Agent copied to clipboard

Bug: Discovery packet for each sensor is resent every 30 seconds

Open karwosts opened this issue 2 years ago • 4 comments

Describe the bug

My Homeassistant log is overwhelmed with MQTT discovery messages saying its getting discovery for already discovered component. This comes in every 30 seconds, for each HASS.Agent sensor I have configured.

2023-03-17 07:31:17.052 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor TIM-PC tim-pc_loggeduser, sending update
2023-03-17 07:31:47.428 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor TIM-PC tim-pc_loggeduser, sending update
2023-03-17 07:32:17.824 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor TIM-PC tim-pc_loggeduser, sending update

Looking in MQTT-Explorer, I confirm a new config packet comes every 30 seconds.

Why is this happening so often?

To Reproduce Steps to reproduce the behavior:

  1. Create a HASS.Agent sensor
  2. ???
  3. Get MQTT spam

Expected behavior I would only expect to see one config packet per sensor, at first connection, or when something significant changes that requires a new config packet.

Screenshots image

Misc info (please complete the following information):

  • Windows build (ideally screenshot/info of winver.exe output):

image

  • Windows' UI language: English
  • HASS.Agent version: 2022.14.0

Please check what's applicable (multiple answers possible):

  • [x] Installed via installer
  • [ ] Installed manually
  • [x] Problem occurs in HASS.Agent
  • [ ] Problem occurs in Satellite Service

Additional context Add any other context about the problem here.

Logs If possible, please provide the logs of HASS.Agent and - if applicable - the Satellite Service. You can find HASS.Agent's logs by going to the main window, then Configuration -> Logging -> open logs folder. The Satellite Service's logs are in the same window, but the Satellite Service tab -> open service logs folder. If you want, you can mail them to [email protected]

karwosts avatar Mar 17 '23 14:03 karwosts

I too am seeing this but mine is every 10 seconds, which is the frequency of the lastactive sensor updates.

2023-03-24 01:20:34.212 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_lastactive, sending update
2023-03-24 01:20:34.213 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_sessionstate, sending update
2023-03-24 01:20:34.214 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_monitorpowerstate, sending update
2023-03-24 01:20:35.432 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorsleep, sending update
2023-03-24 01:20:35.437 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorwake, sending update
2023-03-24 01:20:35.438 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_restart, sending update
2023-03-24 01:21:04.705 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_lastactive, sending update
2023-03-24 01:21:04.708 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_sessionstate, sending update
2023-03-24 01:21:04.709 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_monitorpowerstate, sending update
2023-03-24 01:21:05.437 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorsleep, sending update
2023-03-24 01:21:05.442 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorwake, sending update
2023-03-24 01:21:05.446 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_restart, sending update
2023-03-24 01:21:35.162 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_lastactive, sending update
2023-03-24 01:21:35.166 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_sessionstate, sending update
2023-03-24 01:21:35.169 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor WINDOWS-11 WINDOWS-11_monitorpowerstate, sending update
2023-03-24 01:21:35.444 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorsleep, sending update
2023-03-24 01:21:35.447 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_monitorwake, sending update
2023-03-24 01:21:35.449 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: button WINDOWS-11 WINDOWS-11_restart, sending update

danielbrunt57 avatar Mar 24 '23 08:03 danielbrunt57

I too get this a lot, why is the component "rediscovered" again?

2023-06-09 20:46:40.848 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor ** **__ConnectionType, sending update
2023-06-09 20:46:40.857 INFO (MainThread) [homeassistant.components.mqtt.discovery] Component has already been discovered: sensor ** **__UserNotificationStateSensor, sending update

continuing that way the next 35 sensors in line with lastactive update frequency...

the hass.agent log does not contain any hint for the time the issue occurs, ther is no further entry after 20:40:15

2023-06-09 20:39:19.771 +02:00 [INF] [MAIN] HASS.Agent version: 2022.14.0
2023-06-09 20:39:19.775 +02:00 [INF] [MAIN] Extended logging enabled
2023-06-09 20:39:19.779 +02:00 [INF] [SETTINGS] Config storage path: C:\Users\alex\AppData\Roaming\LAB02 Research\HASS.Agent\config
2023-06-09 20:39:19.931 +02:00 [INF] [SETTINGS] Configuration loaded
2023-06-09 20:39:19.935 +02:00 [INF] [LOCALIZATION] Selected UI culture: [en] English
2023-06-09 20:39:20.226 +02:00 [INF] [SETTINGS_QUICKACTIONS] Loaded 5 entities
2023-06-09 20:39:20.245 +02:00 [INF] [SETTINGS_COMMANDS] Loaded 9 entities
2023-06-09 20:39:21.427 +02:00 [INF] [BLUETOOTH] LE scanner started
2023-06-09 20:39:32.269 +02:00 [FTL] [PROGRAM] FirstChanceException: Element not found. (0x80070490)
System.Runtime.InteropServices.COMException (0x80070490): Element not found. (0x80070490)
   at System.Runtime.InteropServices.Marshal.ThrowExceptionForHR(Int32 errorCode)
   at CoreAudio.AudioSessionManager2.UnregisterNotifications()
2023-06-09 20:39:32.744 +02:00 [INF] [SETTINGS_SENSORS] Loaded 18 entities
2023-06-09 20:39:32.759 +02:00 [INF] [LOCALAPI] Disabled
2023-06-09 20:39:32.759 +02:00 [INF] [SERVICE] Local install path: C:\Program Files (x86)\LAB02 Research\HASS.Agent Satellite Service\
2023-06-09 20:39:32.759 +02:00 [INF] [MQTT] Identifying as device: **
2023-06-09 20:39:32.774 +02:00 [INF] [MQTT] Connecting ..
2023-06-09 20:39:32.780 +02:00 [INF] [HOTKEY] Completed bind for global quickaction hotkey
2023-06-09 20:39:32.833 +02:00 [INF] [MEDIA] Ready
2023-06-09 20:39:32.842 +02:00 [INF] [NOTIFIER] Ready
2023-06-09 20:39:32.861 +02:00 [INF] [MEDIA] Now playing: E. Wolf - Best Shuffle Dance Music 2022 ♫ Melbourne Bounce Music 2022 ♫ Electro House Party Dance
2023-06-09 20:39:32.890 +02:00 [WRN] [MQTT] Not connected, message dropped (won't report again for 5 minutes)
2023-06-09 20:39:32.891 +02:00 [INF] [MEDIA] New state: Playing
2023-06-09 20:39:32.908 +02:00 [INF] [HASS_API] Home Assistant version: 2023.6.1
2023-06-09 20:39:32.915 +02:00 [INF] [MQTT] Connected
2023-06-09 20:39:33.787 +02:00 [INF] [HASS_API] System connected with https://**********:8443
2023-06-09 20:39:34.814 +02:00 [INF] [MQTT] Initial registration completed
2023-06-09 20:40:15.506 +02:00 [FTL] [PROGRAM] FirstChanceException: Element not found. (0x80070490)
System.Runtime.InteropServices.COMException (0x80070490): Element not found. (0x80070490)
   at CoreAudio.AudioSessionManager2.UnregisterNotifications()

NODeeJay avatar Jun 09 '23 18:06 NODeeJay

Also having the same issues with the discovery message every 30 seconds. Very similar error in the extended log too

2023-06-25 11:34:19.829 +01:00 [INF] [MAIN] HASS.Agent version: 2022.14.0
2023-06-25 11:34:19.831 +01:00 [INF] [MAIN] Extended logging enabled
2023-06-25 11:34:19.834 +01:00 [INF] [SETTINGS] Config storage path: C:\Users\me\AppData\Roaming\LAB02 Research\HASS.Agent\config
2023-06-25 11:34:19.927 +01:00 [INF] [SETTINGS] Configuration loaded
2023-06-25 11:34:19.930 +01:00 [INF] [LOCALIZATION] Selected UI culture: [en] English
2023-06-25 11:34:20.119 +01:00 [INF] [SETTINGS_QUICKACTIONS] Config not found, no entities loaded
2023-06-25 11:34:20.138 +01:00 [INF] [SETTINGS_COMMANDS] Loaded 2 entities
2023-06-25 11:34:25.101 +01:00 [INF] [SETTINGS_SENSORS] Loaded 4 entities
2023-06-25 11:34:25.108 +01:00 [INF] [MQTT] Identifying as device: SPEEDY2
2023-06-25 11:34:25.108 +01:00 [INF] [LOCALAPI] Disabled
2023-06-25 11:34:25.111 +01:00 [INF] [SERVICE] Local install path: C:\Program Files (x86)\LAB02 Research\HASS.Agent Satellite Service\
2023-06-25 11:34:25.116 +01:00 [INF] [MQTT] Connecting ..
2023-06-25 11:34:25.119 +01:00 [INF] [HOTKEY] Completed bind for global quickaction hotkey
2023-06-25 11:34:25.140 +01:00 [INF] [MEDIA] Disabled
2023-06-25 11:34:25.214 +01:00 [INF] [NOTIFIER] Ready
2023-06-25 11:34:25.234 +01:00 [INF] [HASS_API] Home Assistant version: 2023.6.2
2023-06-25 11:34:25.317 +01:00 [INF] [MQTT] Connected
2023-06-25 11:34:25.358 +01:00 [INF] [HASS_API] System connected with https://homeassistant.local:8123
2023-06-25 11:34:27.139 +01:00 [INF] [MQTT] Initial registration completed
2023-06-25 11:36:40.202 +01:00 [FTL] [PROGRAM] FirstChanceException: Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
System.IO.IOException: Unable to read data from the transport connection: The I/O operation has been aborted because of either a thread exit or an application request..
 ---> System.Net.Sockets.SocketException (995): The I/O operation has been aborted because of either a thread exit or an application request.
   --- End of inner exception stack trace ---
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](TIOAdapter adapter, Memory`1 buffer)

OS Info

Edition	Windows 10 Pro
Version	22H2
OS build	19045.3086
Experience	Windows Feature Experience Pack 1000.19041.1000.0

Latest HASS.agent and HomeAssistant using mosquitto for MQTT installed on a separate Pi

Always had this error since the first use of HASA.Agent so I've avoided using it up to now.

pjwerdna avatar Jun 25 '23 10:06 pjwerdna

I have the same problem. Any updates on this one? Thank you ;)

zoesn89 avatar Dec 22 '23 19:12 zoesn89