Recover from dead connections?

[karlvr]

I've removed the timeout from status calls but it seems we can hang there.

Need Timeouts everywhere.

Close and reopen connection?

[karlvr]

@rcoletti116 i think this is what we're both observing with the beta… if you get a chance, could you please post a section of the log before and after it starts to get a failed connection? And a couple of rounds of the connection being failed.

[karlvr]

This is what my logs look like when this happens:

[9/22/2021, 11:20:11 PM] [Roomba] DEBUG: Connecting to Roomba…
[9/22/2021, 11:20:14 PM] [Roomba] DEBUG: Connected to Roomba in 3188ms
[9/22/2021, 11:20:14 PM] [Roomba] DEBUG: getStatus got status in 3801ms: {"netinfo":{"dhcp":true,"addr":167838123,"mask":4294967040,"gw":167838206,"dns1":1678
38206,"dns2":0,"bssid":"74:83:c2:c7:80:6e","sec":4},"wifistat":{"wifi":1,"uap":false,"cloud":1},"wlcfg":{"sec":7,"ssid":"41726B"},"mac":"d0:c5:d3:be:75:b4","c
ountry":"NZ","cloudEnv":"prod","svcEndpoints":{"svcDeplId":"v011"},"wifiAnt":1,"mapUploadAllowed":true,"localtimeoffset":720,"utctime":1632309605,"pose":{"the
ta":-152,"point":{"x":-6,"y":7}},"batPct":100,"dock":{"known":true},"bin":{"present":true,"full":false},"cleanMissionStatus":{"cycle":"none","phase":"stop","e
xpireM":0,"rechrgM":0,"error":0,"notReady":0,"mssnM":0,"mssnStrtTm":0,"expireTm":0,"rechrgTm":0,"sqft":0,"initiator":"localApp","nMssn":676},"language":0,"noA
utoPasses":false,"noPP":false,"ecoCharge":false,"vacHigh":false,"binPause":false,"carpetBoost":true,"openOnly":false,"twoPass":false,"schedHold":false} => {"e
rror":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:20:14 PM] [Roomba] DEBUG: Will check Roomba's status again in 10s (idle timeout in 387s)
[9/22/2021, 11:20:14 PM] [Roomba] DEBUG: Updating characteristics for status: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":10
0,"binFull":false}
[9/22/2021, 11:20:14 PM] [Roomba] DEBUG: Releasing Roomba instance
[9/22/2021, 11:20:24 PM] [Roomba] DEBUG: Connecting to Roomba…
[9/22/2021, 11:20:28 PM] [Roomba] DEBUG: Connected to Roomba in 3467ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Reusing connected Roomba
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Bin status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 3ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Docking status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 5ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Dock status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 6ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 8ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Low Battery status requested
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 10ms
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Running status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Bin status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Docking status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Dock status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Running status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:21:22 PM] [Roomba] DEBUG: Low Battery status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Reusing connected Roomba
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Bin status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 2ms
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Docking status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 4ms
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Dock status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 5ms
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 7ms
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Low Battery status requested
[9/22/2021, 11:22:05 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 8ms
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Running status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Bin status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Docking status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Dock status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Running status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:06 PM] [Roomba] DEBUG: Low Battery status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Reusing connected Roomba
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Bin status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 4ms
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Running status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 6ms
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Dock status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 9ms
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Docking status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 11ms
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Low Battery status requested
[9/22/2021, 11:22:27 PM] [Roomba] DEBUG: Queueing status request with status request that's been running for 13ms
[9/22/2021, 11:22:28 PM] [Roomba] DEBUG: Running status: timeout returning last result: {"error":null,"running":false,"docking":false,"charging":false,"batteryLevel":100,"binFull":false}

Analysis: we can see the plugin reusing a connection over and over again, for hours, and never getting anywhere or closing the connection.

[karlvr]

@rcoletti116 I've pushed a new beta with some radical changes if you're keen to try that out! 1.3.0-beta.3

[rcoletti116]

I've been testing beta.5. It's better but still seeing some inconsistencies with sending commands and receiving status updates. Sometimes the commands don't go through at all, other times it seems they conflict with the status updates.

For example, when I stop the Roomba the device stops, but the main accessory (Roomba Switch) turns back on and shows as on for about another 30 seconds. You can see it in the logs here:

[23/09/2021, 08:33:35] [Roomba] DEBUG: Leaving Roomba instance with 1 ongoing requests
[23/09/2021, 08:33:35] [Roomba] Roomba is pausing
[23/09/2021, 08:33:35] [Roomba] DEBUG: Updating Roomba On from 1 to 0
[23/09/2021, 08:33:35] [Roomba] DEBUG: Updating Roomba Running Contact Sensor State from 1 to 0
[23/09/2021, 08:33:35] [Roomba] Roomba is paused
[23/09/2021, 08:33:35] [Roomba] DEBUG: Releasing Roomba instance
[23/09/2021, 08:33:35] [Roomba] DEBUG: Updating Roomba On from 0 to 1
[23/09/2021, 08:33:35] [Roomba] DEBUG: Updating Roomba Running Contact Sensor State from 0 to 1
[23/09/2021, 08:33:35] [Roomba] DEBUG: Connection close received from old connection
[23/09/2021, 08:34:00] [Roomba] DEBUG: Refreshing Roomba's status (repeating in 30s, idle timeout in 574s)
[23/09/2021, 08:34:00] [Roomba] DEBUG: Connecting to Roomba (0 others waiting)...
[23/09/2021, 08:34:04] [Roomba] DEBUG: Connected to Roomba in 3849ms
[23/09/2021, **08:34:04**] [Roomba] DEBUG: Updating Roomba On from 1 to 0
[23/09/2021, 08:34:04] [Roomba] DEBUG: Updating Roomba Battery Level from 14 to 13
[23/09/2021, 08:34:04] [Roomba] DEBUG: Updating Roomba Running Contact Sensor State from 1 to 0
[23/09/2021, 08:34:04] [Roomba] DEBUG: Refreshed Roomba's state in 4386ms: {"netinfo":{"dhcp":true,"addr":167772420,"mask":4278190080,"gw":167772161,"dns1":167772161,"dns2":0,"bssid":"18:90:88:32:0f:a3","sec":4},"wifistat":{"wifi":1,"uap":false,"cloud":1},"wlcfg":{"sec":7,"ssid":"xxxx"},"mac":"xxx","country":"US","cloudEnv":"prod","svcEndpoints":{"svcDeplId":"v011"},"wifiAnt":1,"mapUploadAllowed":true,"localtimeoffset":-240,"utctime":1632400428,"pose":{"theta":178,"point":{"x":-9,"y":6}},"batPct":13,"dock":{"known":true},"bin":{"present":true,"full":true},"cleanMissionStatus":{"cycle":"clean","phase":"stop","expireM":0,"rechrgM":0,"error":0,"notReady":0,"mssnM":0,"mssnStrtTm":1632400229,"expireTm":1632405798,"rechrgTm":0,"sqft":0,"initiator":"localApp","nMssn":0},"language":0,"noAutoPasses":false,"noPP":false,"ecoCharge":false,"vacHigh":false,"binPause":true,"carpetBoost":true,"openOnly":false,"twoPass":false,"schedHold":false}

[karlvr]

@rcoletti116 how is this behaviour with the latest beta?

[rcoletti116]

This behavior remains unchanged in the latest beta.

[karlvr]

@rcoletti116 thank you. I think I saw the same behaviour yesterday. It seems to be the roomba sending a status to us that doesn't include its most recent change.

Does this happen every time you stop Roomba?

[rcoletti116]

Yes, every time.

[karlvr]

@rcoletti116 maybe beta 8 will improve this behaviour!