Continues losing connection.

[eliogrin]

Hi @ec-blaster, first of all, many thanks for this great plugin, you did a great job!

I faced a bug, maybe you will be able to help me here?

Precondition: Connected successfully, everything works fine, MagicSwitchBot is close to my Home Assistant server.

Scenario: 1) I'm taking MagicSwitchBot and moving to another room (where I planned to install it); 2) Device lose connection; 3) I'm moving MagicSwitchBot back, close to Home Assistant server.

Problem: Each minute device lose connection, staying unavailable for 1 minute and getting back online for the next minute. And it's repeating each 2 minutes, you can check screenshot of history attached. In my case I need reboot home assistant to restore normal connection.

I believe each time when device is losing connection we will have the same behaviour, and it will never get back to stable connection. Is it common issue, or something specific to my environment?

[jampem]

Same problem, Raspberry Pi 3 bluetooth:

2021-03-23 16:33:11 ERROR (MainThread) [magicswitchbot] MagicSwitchbot communication failed. We won't try again. NoneType: None 2021-03-23 16:33:11 WARNING (MainThread) [custom_components.magicswitchbot.switch] Couldn't get battery level of switch.magic 2021-03-23 16:33:58 INFO (MainThread) [pyhap.hap_protocol] ('192.168.1.126', 55521): Connection made to HASS Bridge QFF1 2021-03-23 16:34:10 INFO (MainThread) [magicswitchbot] Connected to MagicSwitchbot at 34:14:B5:4A:2E:07 from hci0 2021-03-23 16:34:11 INFO (MainThread) [magicswitchbot] Command sent to MagicSwitchbot (34:14:B5:4A:2E:07): 92da5370eb71f9116ad9c294231a4c17 2021-03-23 16:34:11 INFO (MainThread) [magicswitchbot] Response: [Command = 02, Return Code = 02, Length = 1, Params = 3d] 2021-03-23 16:34:11 INFO (MainThread) [magicswitchbot] Battery level retrieved: 61 2021-03-23 16:35:08 WARNING (MainThread) [magicswitchbot] MagicSwitchbot communication error: Device disconnected 2021-03-23 16:35:08 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 3)... 2021-03-23 16:35:09 WARNING (MainThread) [magicswitchbot] MagicSwitchbot communication error: Helper not started (did you call connect()?) 2021-03-23 16:35:09 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 2)... 2021-03-23 16:35:09 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 1)... 2021-03-23 16:35:09 ERROR (MainThread) [magicswitchbot] MagicSwitchbot communication failed. We won't try again. NoneType: None 2021-03-23 16:35:09 WARNING (MainThread) [custom_components.magicswitchbot.switch] Couldn't get battery level of switch.magic 2021-03-23 16:36:11 ERROR (MainThread) [homeassistant.helpers.entity] Update for switch.magic fails Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 277, in async_update_ha_state await self.async_device_update() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 473, in async_device_update raise exc File "/config/custom_components/magicswitchbot/switch.py", line 142, in async_update self._battery_level = self._device.get_battery() File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 628, in get_battery ok = self._sendCommand(self.CMD_GETBAT, "01", self._retry_count) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 438, in _sendCommand self._connect() File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 236, in _connect self._device = PeripheralExt(deviceAddr=self._mac, File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 37, in init self._connect(deviceAddr, addrType, iface, timeout) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 56, in _connect while rsp['state'][0] == 'tryconn': TypeError: 'NoneType' object is not subscriptable 2021-03-23 16:37:10 INFO (MainThread) [magicswitchbot] Connected to MagicSwitchbot at 34:14:B5:4A:2E:07 from hci0 2021-03-23 16:37:11 INFO (MainThread) [magicswitchbot] Command sent to MagicSwitchbot (34:14:B5:4A:2E:07): 0f936c79aa3ef83701db15cfe39a18a9 2021-03-23 16:37:11 INFO (MainThread) [magicswitchbot] Response: [Command = 02, Return Code = 02, Length = 1, Params = 3d] 2021-03-23 16:37:11 INFO (MainThread) [magicswitchbot] Battery level retrieved: 61 2021-03-23 16:38:08 WARNING (MainThread) [magicswitchbot] MagicSwitchbot communication error: Device disconnected 2021-03-23 16:38:08 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 3)... 2021-03-23 16:38:09 WARNING (MainThread) [magicswitchbot] MagicSwitchbot communication error: Helper not started (did you call connect()?) 2021-03-23 16:38:09 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 2)... 2021-03-23 16:38:09 WARNING (MainThread) [magicswitchbot] Cannot send command to MagicSwitchbot. Retrying (remaining attempts: 1)... 2021-03-23 16:38:09 ERROR (MainThread) [magicswitchbot] MagicSwitchbot communication failed. We won't try again. NoneType: None 2021-03-23 16:38:09 WARNING (MainThread) [custom_components.magicswitchbot.switch] Couldn't get battery level of switch.magic 2021-03-23 16:39:10 INFO (MainThread) [magicswitchbot] Connected to MagicSwitchbot at 34:14:B5:4A:2E:07 from hci0 2021-03-23 16:39:10 INFO (MainThread) [magicswitchbot] Command sent to MagicSwitchbot (34:14:B5:4A:2E:07): e0fc5dbc7fadb10f7c3284018da37e3d 2021-03-23 16:39:10 INFO (MainThread) [magicswitchbot] Response: [Command = 02, Return Code = 02, Length = 1, Params = 3d] 2021-03-23 16:39:10 INFO (MainThread) [magicswitchbot] Battery level retrieved: 61

[ec-blaster]

Thanks @eliogrin and @jampem

Yesterday I had a similar issue, but now it is running quite stable for me:

I think there are several problems here:

1. The bluetooth connection has a bad quality. Something happens with the bluetooh connection that breaks from time to time if the HA node and the magicswitchbot are not near enough. I solved it by connecting an external bluetooth adapter with an extension cable. From that moment, it went fantastic.
2. The library I am using (bluepy) has no way to detect when the connection breaks. So what happens is:
   • Every minute I check the bot battery.
   • If it is not connected, it tries to connect (up to 3 times).
   • After connecting it should read the battery level and the connection would be alive again.

That's the theory, but as I can see at your logs, if the device does not connect after 3 attempts, it stops trying and continues at the next minute.

Things to consider and that I have to fix:

• The switches are polled to get their battery levels every minute. I should allow the users to configure this scan period.
• If the device does not connect in 3 seconds, it gives up. I think this connect timeout should also be configurable, but there's a problem: I can only detect the connection fail when I am going to read the battery level, but if you set a high timeout, this blocks Home Assistant "loop", so it may affect the whole system stability. That happened to me before I set this timeout.

Definitely I have to implement some alternate strategy for the disconnection check. I'll make some tests and publish a fix as soon as possible. In the meantime, I can advise you to get the sensors as near as possible to the HA server, or get an extension cable and a higher power bluetooth dongle.

[eliogrin]

@ec-blaster thanks for response. Yes, I'm going to order bluetooth dongle, because of unstable connection, it's definitely not a problem on your side :). But problem which I was raised here, is mainly about unavailability to restore stable connection after loosing it once. At least in my case I was able to restore stable connection only by restarting home assistant. Even when I put device next to my Raspberry Pi it connection wasn't back to normal.

I'm not so experienced with creating plugins, but just as an idea, is it possible to not keep connection active for the whole time? So whenever there is click action - you will establish connection and send request. At least in my case I need to change the state pretty rarely (few times per day).

[ec-blaster]

In my case (and I think that also for @jampem) the connection does restore over time, I don't have to restart HA. The problem is that it doesn't connect on time when it's needed.

So for the second question, I'm not too experienced either, neither with HA development nor Python development. My first attempt was in fact connecting every time I needed to access the switch, but in my tests, the connection time (including the time you need to get all the acknolewgments and the connection token) was taking too long to do it at the moment you needed. It could take up to 7-8 seconds to activate the switch, and I thought that would not be normal...

[jampem]

I tried old Epox external bluetooth dongle and 0.5 meters from dongle to switch, same same, not working (Btw old switchbot works ok):

[ec-blaster]

Some thoughts while I am searching for a solution:

• Did you disconnect the Magic Swtichbot devices from its smartphone app? Maybe there are 2 clients fighting when connecting to the devices. There's only a connection that can be stablished. If you connect with the app you cannot from HA, and viceversa.
• There appears to be some problems using bluetooth with Raspberry:
  • https://stackoverflow.com/questions/65366042/bluepy-frequent-ble-disconnects-between-raspberry-pi4-and-esp32-bluetooth
  • https://github.com/RPi-Distro/firmware-nonfree/issues/8

Anyway I am rethinking the way the library connects, in next releases I hope to fix it.

[jampem]

I did disconnect Magic from my iPhone and as I said "the old SwitchBot" works ok. Also tried external bluetooth stick.

[ec-blaster]

Please check the v0.0.3 release.

I hope it solves some of your connection problems...

[chronoszgz]

At the moment it works perfectly ec-blaster!! Very good job!! Thank you very much!!

[jampem]

Raspberry 3 internal bluetooth, working little better but still some problems, I will try external bluetooth dongle soon: 2021-03-29 17:32:57 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 06010054f260aeea655114b8bfad0855 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = 408b61c70102000700) 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is 408b61c7 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 02010101408b61c7e94dccbb691b6d85 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 02, Return Code = 02, Length = 1, Params = 32) 2021-03-29 17:32:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Battery level: 50% 2021-03-29 17:33:09 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 05010101408b61c72b4d8c01d7f74171 2021-03-29 17:33:10 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-29 17:33:10 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-29 17:33:10 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-29 17:33:10 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 02010101408b61c7af7385663f135d69 2021-03-29 17:33:11 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication error: Device disconnected 2021-03-29 17:33:11 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (1 of 3 attempts) 2021-03-29 17:33:11 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (2 of 3 attempts) 2021-03-29 17:33:12 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (3 of 3 attempts) 2021-03-29 17:33:12 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication failed. Remaining attempts: 3... 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 0601003d457bb1df443a040009f8568d 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = e30f47430102000700) 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is e30f4743 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-29 17:33:16 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 02010101e30f474351ad6caed2cf0f6d 2021-03-29 17:33:17 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 02, Return Code = 02, Length = 1, Params = 32) 2021-03-29 17:33:17 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Battery level: 50% 2021-03-29 17:33:17 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-29 17:33:23 INFO (Thread-230) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Client disconnected 2021-03-29 17:33:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-29 17:33:40 WARNING (Thread-234) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Unexpected response (desc) when checking connection state (1 of 3 attempts) 2021-03-29 17:33:47 WARNING (Thread-237) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] 'NoneType' object has no attribute 'poll' when checking connection state (2 of 3 attempts) 2021-03-29 17:33:47 INFO (Thread-234) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Client disconnected 2021-03-29 17:33:47 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [1629643560] 'NoneType' object has no attribute 'poll' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 141, in handle_call_service await hass.services.async_call( File "/usr/src/homeassistant/homeassistant/core.py", line 1488, in async_call task.result() File "/usr/src/homeassistant/homeassistant/core.py", line 1523, in _execute_service await handler.job.target(service_call) File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service await self.hass.helpers.service.entity_service_call( File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 642, in entity_service_call future.result() # pop exception if have File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 681, in async_request_call await coro File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 679, in _handle_entity_call await result File "/config/custom_components/magicswitchbot/switch.py", line 132, in async_turn_off if self._device.turn_off(): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 705, in turn_off return self._sendCommand(self.CMD_SWITCH, self.PAR_SWITCHOFF, self._retry_count) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 520, in _sendCommand if self._connect(connect_timeout=self._connectTimeout, retries=retries): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 282, in _connect self._cccdDescriptor = self._userReadChar.getDescriptors(forUUID=self.UUID_NOTIFY_SET)[0] File "/usr/local/lib/python3.8/site-packages/bluepy/btle.py", line 208, in getDescriptors for desc in self.peripheral.getDescriptors(self.valHandle+1, hndEnd): File "/usr/local/lib/python3.8/site-packages/bluepy/btle.py", line 524, in getDescriptors resp = self._getResp('desc') File "/usr/local/lib/python3.8/site-packages/bluepy/btle.py", line 407, in _getResp resp = self._waitResp(wantType + ['ntfy', 'ind'], timeout) File "/usr/local/lib/python3.8/site-packages/bluepy/btle.py", line 338, in _waitResp if self._helper.poll() is not None: AttributeError: 'NoneType' object has no attribute 'poll' 2021-03-29 17:33:47 WARNING (Thread-237) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] 'NoneType' object has no attribute 'getState' when checking connection state (3 of 3 attempts) 2021-03-29 17:33:47 ERROR (Thread-237) [root] Uncaught thread exception Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 381, in _is_connected conn_status = self._device.getState() AttributeError: 'NoneType' object has no attribute 'getState' During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/local/lib/python3.8/threading.py", line 932, in _bootstrap_inner self.run() File "/usr/local/lib/python3.8/threading.py", line 1254, in run self.function(*self.args, **self.kwargs) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 352, in _disconnect if not self._is_connected(): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 390, in _is_connected self._device.disconnect() AttributeError: 'NoneType' object has no attribute 'disconnect' 2021-03-29 17:33:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [1629643560] 'NoneType' object is not subscriptable Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 141, in handle_call_service await hass.services.async_call( File "/usr/src/homeassistant/homeassistant/core.py", line 1488, in async_call task.result() File "/usr/src/homeassistant/homeassistant/core.py", line 1523, in _execute_service await handler.job.target(service_call) File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service await self.hass.helpers.service.entity_service_call( File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 642, in entity_service_call future.result() # pop exception if have File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 681, in async_request_call await coro File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 679, in _handle_entity_call await result File "/config/custom_components/magicswitchbot/switch.py", line 132, in async_turn_off if self._device.turn_off(): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 705, in turn_off return self._sendCommand(self.CMD_SWITCH, self.PAR_SWITCHOFF, self._retry_count) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 520, in _sendCommand if self._connect(connect_timeout=self._connectTimeout, retries=retries): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 272, in _connect self._device = PeripheralExt(deviceAddr=self._mac, File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 50, in init self._connect(deviceAddr, addrType, iface, timeout) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 69, in _connect while rsp['state'][0] == 'tryconn': TypeError: 'NoneType' object is not subscriptable

[ec-blaster]

Hi, @jampem, thanks for your feedback.

From what I can read at your logs, it seems like you have a quite unstable connection to the Magic Switchbot device. Your raspberry starts connecting but, in about 6 or 7 seconds max, the device falls the connection. Maybe with an USB BT dongle things get better... I don't know. In my experience, I got to connect a BT dongle with an extension cable, so that the dongle was as near as possible. I have a pair of walls in between though.

Anyway I can see an uncontrolled exception in my code, and it would be helpful if you could provide another log with DEBUG level set.

Thanks

[ec-blaster]

To @jampem: You can test now release v0.0.4. It has better exception catching. At least your logs will be cleaner and clearer, I hope

[jampem]

Hi, Sorry the last message was from external bluetooth dongle. Here is RB3 internal and the 0.04 ver.

And RB3 and switch are less than a meter apart:

2021-03-30 11:14:57 ERROR (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Couldn't connect to device (Failed to connect to peripheral 34:14:B5:4A:2E:07, addr type: public) 2021-03-30 11:15:00 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci0. 2021-03-30 11:15:01 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-30 11:15:01 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 060100191db5e34924cd86ddc38c225c 2021-03-30 11:15:02 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication error: Device disconnected 2021-03-30 11:15:02 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (1 of 3 attempts) 2021-03-30 11:15:02 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (2 of 3 attempts) 2021-03-30 11:15:03 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (3 of 3 attempts) 2021-03-30 11:15:03 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication failed. Remaining attempts: 3... 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci0. 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 060100733bfb8c8378f7d9c572e3abeb 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = 4e9a8fef0102000700) 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is 4e9a8fef 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-30 11:15:05 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 050101014e9a8fef1a857911209b5e9c 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 020101014e9a8fef5ef87bf07ca54c6b 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 02, Return Code = 02, Length = 1, Params = 32) 2021-03-30 11:15:06 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Battery level: 50% 2021-03-30 11:15:07 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Unexpected response (ntfy) when checking connection state (1 of 3 attempts) 2021-03-30 11:15:31 INFO (Thread-136) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Client disconnected

[ec-blaster]

From your logs and bluetoothctl output, I can see that you have constant disconnection issues with the device. I can't help you here, as this is not relative to my component, it's a lower level problem. I don't know if it's a problem with the RB or with the device, but the connection is not stable to proccess the commands that the component sends.

Does it work OK from the official app? Doesn't it disconnect?

Another thing you can try is to reset the device. I had to do it once: just press the button for about 3-5 seconds until the red led is steady. Then press it again for another 3-5 seconds until the led is blinking. After that, try to reconnect. Hope it helps.

[jampem]

It works fine with official app. Also SwitchBot (the old original, battery operated) works ok with Home Assistant's internal bluetooth. I will try with another RBPi3 during Easter.

Here is log from external bluetooth dongle:

2021-03-31 22:47:38 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 060100d00d66521bddd9d2703d56a750 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = 7b5b85810102000700) 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is 7b5b8581 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-31 22:47:39 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 050101007b5b8581faa62234fa2f1b7e 2021-03-31 22:47:40 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-31 22:47:40 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-31 22:47:40 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:47:40 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 020101017b5b8581d1d7f9248dbb4d9f 2021-03-31 22:47:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 050101017b5b85819c74a2da99c10d89 2021-03-31 22:47:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-31 22:47:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-31 22:47:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:47:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 020101017b5b8581297beff38ebfda13 2021-03-31 22:47:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 050101007b5b858178fbdba83c483791 2021-03-31 22:47:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-31 22:47:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-31 22:47:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:47:58 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 020101017b5b8581b0b7cdc60a89dc2c 2021-03-31 22:47:59 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication error: Device disconnected 2021-03-31 22:47:59 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (1 of 3 attempts) 2021-03-31 22:48:00 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (2 of 3 attempts) 2021-03-31 22:48:00 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Helper not started (did you call connect()?) when checking connection state (3 of 3 attempts) 2021-03-31 22:48:00 WARNING (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Communication failed. Remaining attempts: 3... 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 060100206040f067276fc24c0bd90db8 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = ab5ab4950102000700) 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is ab5ab495 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-31 22:48:03 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 02010101ab5ab495f08ff42d4ae925dd 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 02, Return Code = 02, Length = 1, Params = 2e) 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Battery level: 46% 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 05010100ab5ab4951ac4b8e558cfeebc 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-31 22:48:04 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 02010101ab5ab495d64740b6cc322970 2021-03-31 22:48:28 INFO (Thread-99) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Client disconnected 2021-03-31 22:48:49 ERROR (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Error getting device info Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 272, in _connect self._device = PeripheralExt(deviceAddr=self._mac, File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 50, in init self._connect(deviceAddr, addrType, iface, timeout) File "/usr/local/lib/python3.8/site-packages/magicswitchbot/init.py", line 69, in _connect while rsp['state'][0] == 'tryconn': TypeError: 'NoneType' object is not subscriptable 2021-03-31 22:48:50 ERROR (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Couldn't connect to device (Failed to connect to peripheral 34:14:B5:4A:2E:07, addr type: public) 2021-03-31 22:48:51 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Connected with hci1. 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETTOKEN command: 060100d83723cdacaabc317527010913 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 06, Return Code = 02, Length = 9, Params = 8493eb020102000700) 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] The current connection token is 8493eb02 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Chip type: 01, Firmware version: 2.0, Device type: 07, Password enabled: False 2021-03-31 22:48:52 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_SWITCH command: 050101018493eb02fe6ba47b8a01062e 2021-03-31 22:48:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Response: (Command = 05, Return Code = 02, Length = 1, Params = 00) 2021-03-31 22:48:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Switch state changed successfully 2021-03-31 22:48:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Auto-disconnect scheduled for 30 seconds. 2021-03-31 22:48:53 INFO (MainThread) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Sending CMD_GETBAT command: 020101018493eb02241b1ad4db0f843f 2021-03-31 22:49:23 INFO (Thread-109) [magicswitchbot] MagicSwitchbot[34:14:B5:4A:2E:07] Client disconnected

[ec-blaster]

You can check newer releases, they control better the exceptions, but the underlying problem is a bad connectivity issue. Read comments in #4 as the look the same.