Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Continues losing connection. #1

Closed
eliogrin opened this issue Mar 23, 2021 · 16 comments
Closed

Continues losing connection. #1

eliogrin opened this issue Mar 23, 2021 · 16 comments
Assignees
Labels
bug Something isn't working

Comments

@eliogrin
Copy link

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.
IMG_3120

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
Copy link

jampem commented Mar 23, 2021

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
Copy link
Owner

Thanks @eliogrin and @jampem

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

imagen

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.

@ec-blaster ec-blaster self-assigned this Mar 23, 2021
@eliogrin
Copy link
Author

@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
Copy link
Owner

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
Copy link

jampem commented Mar 23, 2021

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

bluetoothctl

@ec-blaster
Copy link
Owner

Some thoughts while I am searching for a solution:

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

@ec-blaster ec-blaster added the bug Something isn't working label Mar 24, 2021
@jampem
Copy link

jampem commented Mar 24, 2021

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

@ec-blaster
Copy link
Owner

Please check the v0.0.3 release.

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

@chronoszgz
Copy link

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

@jampem
Copy link

jampem commented Mar 29, 2021

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
Copy link
Owner

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
Copy link
Owner

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
Copy link

jampem commented Mar 30, 2021

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

Screenshot 2021-03-30 at 11 15 49

@ec-blaster
Copy link
Owner

ec-blaster commented Mar 30, 2021

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
Copy link

jampem commented Mar 31, 2021

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
Copy link
Owner

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants