too much logging

[solbadguy2010]

Expected Behavior

only create log-entries when there are "real" errors when "extendet logging" is not active in homebridge

Current Behavior

[29/03/2022, 05:24:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:24:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:24:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:25:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:25:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:25:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:26:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:26:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:26:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:27:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:27:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:27:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:28:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:28:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:28:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:29:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:29:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:29:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:30:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:30:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:30:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:31:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:31:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:31:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:32:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:32:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:32:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:33:22] [Roomba] Timed out after 59999ms trying to connect to Roomba [29/03/2022, 05:33:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:33:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:34:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:34:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:34:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:35:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [29/03/2022, 05:35:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:35:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:36:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:36:22] [Roomba] Releasing an unexpected Roomba instance [29/03/2022, 05:36:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out [29/03/2022, 05:37:22] [Roomba] Timed out after 60000ms trying to connect to Roomba [29/03/2022, 05:37:22] [Roomba] Releasing an unexpected Roomba instance

Steps to Reproduce (for bugs)

Battery of Roomby empty

[ArtemKiyashko]

Have similar logs (Releasing an unexpected Roomba instance), but battery full and attached. Roomba operational via official app. After some long time (e.g. several hours maybe) have a long delays between the command in homebridge UI and action

[01/04/2022, 00:05:52] [Roomba] DEBUG: Releasing Roomba instance [01/04/2022, 00:05:52] [Roomba] DEBUG: Refreshing Roomba's status (repeating in 1m) [01/04/2022, 00:05:52] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:05:52] [Roomba] DEBUG: Connection close received [01/04/2022, 00:05:56] [Roomba] DEBUG: Connected to Roomba in 4257ms [01/04/2022, 00:06:52] [Roomba] DEBUG: Refreshing Roomba's status (repeating in 1m) [01/04/2022, 00:06:52] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:06:52] [Roomba] DEBUG: Connection close received [01/04/2022, 00:06:56] [Roomba] DEBUG: Timeout waiting for full state from Roomba ({}ms). Last state received was: 60001 {"netinfo":{"dhcp":true,"addr":3232235934,"mask":4294967040,"gw":3232235777,"dns1":3232235834,"dns2":3232235777,"bssid":"f0:2f:74:f2:13:19","sec":4},"wifistat":{"wifi":1,"uap":false,"cloud":1},"wlcfg":{"sec":7,"ssid":"736F6C79616E6B61"},"mac":"80:91:33:ce:b5:40","country":"RU","cloudEnv":"prod","svcEndpoints":{"svcDeplId":"v011"},"wifiAnt":1,"signal":{"rssi":-51,"snr":38}} [01/04/2022, 00:06:56] [Roomba] Releasing an unexpected Roomba instance [01/04/2022, 00:07:00] [Roomba] DEBUG: Connected to Roomba in 8362ms [01/04/2022, 00:07:52] [Roomba] DEBUG: Refreshing Roomba's status (repeating in 1m) [01/04/2022, 00:07:52] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:07:52] [Roomba] DEBUG: Connection close received [01/04/2022, 00:07:52] [Roomba] DEBUG: Running status: Returning no value (5006ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Low Battery status: Returning no value (5007ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Battery level: Returning no value (5008ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Charging status: Returning no value (5008ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Bin status: Returning no value (5009ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Dock status: Returning no value (5009ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Running status: Returning no value (5010ms old) [01/04/2022, 00:07:52] [Roomba] DEBUG: Bin status: Returning no value (5010ms old) [01/04/2022, 00:07:57] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 595s) [01/04/2022, 00:08:00] [Roomba] DEBUG: Timeout waiting for full state from Roomba ({}ms). Last state received was: 60001 {"netinfo":{"dhcp":true,"addr":3232235934,"mask":4294967040,"gw":3232235777,"dns1":3232235834,"dns2":3232235777,"bssid":"f0:2f:74:f2:13:19","sec":4},"wifistat":{"wifi":1,"uap":false,"cloud":1},"wlcfg":{"sec":7,"ssid":"736F6C79616E6B61"},"mac":"80:91:33:ce:b5:40","country":"RU","cloudEnv":"prod","svcEndpoints":{"svcDeplId":"v011"},"wifiAnt":1,"signal":{"rssi":-46,"snr":44}} [01/04/2022, 00:08:00] [Roomba] Releasing an unexpected Roomba instance [01/04/2022, 00:08:02] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 590s) [01/04/2022, 00:08:02] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:08:02] [Roomba] DEBUG: Connection close received [01/04/2022, 00:08:04] [Roomba] DEBUG: Connected to Roomba in 12461ms [01/04/2022, 00:08:07] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 584s) [01/04/2022, 00:08:12] [G-On Alice] aliceDiscovery - returned 10 devices [01/04/2022, 00:08:12] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 579s) [01/04/2022, 00:08:12] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:08:12] [Roomba] DEBUG: Connection close received [01/04/2022, 00:08:17] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 574s) [01/04/2022, 00:08:22] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 569s) [01/04/2022, 00:08:22] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)... [01/04/2022, 00:08:22] [Roomba] DEBUG: Connection close received [01/04/2022, 00:08:27] [Roomba] DEBUG: Watching Roomba's status (repeating in 5s, idle timeout in 564s)

Logs after some time:

[01/04/2022, 00:13:22] [Roomba] Timed out after 60001ms trying to connect to Roomba [01/04/2022, 00:13:22] [Roomba] Releasing an unexpected Roomba instance [01/04/2022, 00:13:22] [Roomba] Failed to connect to Roomba to refresh state: Connect timed out

Update

Additionally i've got some messages from node.js, not sure, but it can be important (i`ve seen similar reports in other HB plugins, so maybe the issue is on HB side):

(node:9126) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [MqttClient]. Use emitter.setMaxListeners() to increase limit (Use node --trace-warnings ... to show where the warning was created) (node:9126) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added to [MqttClient]. Use emitter.setMaxListeners() to increase limit (node:9126) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 state listeners added to [MqttClient]. Use emitter.setMaxListeners() to increase limit

[solbadguy2010]

@ArtemKiyashko Yours is another Topic than mine. Mine happens when the battery is empty. I only want less log entires. Yours looks like a connection problem. Please create your own issue.

[karlvr]

@solbadguy2010 it's tricky to distinguish between whether there's a problem connecting to Roomba due to something you're interested in, or something you're not (battery flat). I'll try to reduce the frequency with which it logs communications failures!

[solbadguy2010]

Thats nice. Thank you. I sold my Roomba some months ago. Sadly i can not test anymore.

[karlvr]

I have reduced the number of log entries seen above. I will continue to monitor the number of log entries when Roomba can't be reached... by default it should be only one every 15 minutes now while no one is using the Home app.