search

dauden1184 / RaspiNukiBridge

Simple Nuki Bridge implementation using asyncio
GNU General Public License v3.0
47 stars 19 forks source link

bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] In Progress #24

Open techn0tr0ll opened 1 year ago

techn0tr0ll commented 1 year ago

Hey there (again),

we have some weird issues with our setup when we trigger the API calls at some time but not always. Mostly the error occured after the lock / api was unused for some time (~ hours / days)

The following Logging shows the error message.

2023-07-05 16:55:17.851|I|nuki.py:625|Lock action 3
2023-07-05 16:55:17.857|I|nuki.py:173|Stop scanning
2023-07-05 16:55:26.760|I|nuki.py:569|Nuki connecting
2023-07-05 16:55:33.548|I|nuki.py:581|Connected
2023-07-05 16:55:33.705|E|nuki.py:549|Error: <class 'bleak.exc.BleakDBusError'> [org.bluez.Error.InProgress] In Progress
Traceback (most recent call last):
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 547, in _send_data
    await self._client.write_gatt_char(characteristic, data)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 800, in write_gatt_char
    assert_reply(reply)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] In Progress
2023-07-05 16:55:33.714|E|nuki.py:549|Error: <class 'bleak.exc.BleakDBusError'> [org.bluez.Error.InProgress] In Progress
Traceback (most recent call last):
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 547, in _send_data
    await self._client.write_gatt_char(characteristic, data)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 800, in write_gatt_char
    assert_reply(reply)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] In Progress
2023-07-05 16:55:33.774|E|nuki.py:497|Last action: {'status': <StatusCode.ACCEPTED: 1>}
2023-07-05 16:55:33.778|E|nuki.py:497|Last action: {'status': <StatusCode.ACCEPTED: 1>}
2023-07-05 16:55:33.783|E|nuki.py:497|Last action: {'status': <StatusCode.ACCEPTED: 1>}
2023-07-05 16:55:33.850|I|nuki.py:461|State: {'nuki_state': <NukiState.DOOR_MODE: 2>, 'lock_state': <LockState.UNLATCHING: 7>, 'trigger': 0, 'current_time': datetime.datetime(2023, 7, 5, 16, 56), 'timezone_offset': 120, 'critical_battery_state': 120, 'current_update_count': 5, 'lock_n_go_timer': 0, 'last_lock_action': <NukiAction.UNLATCH: 3>, 'last_lock_action_trigger': 0, 'last_lock_action_completion_status': 0, 'door_sensor_state': <DoorsensorState.UNAVAILABLE: 0>, 'nightmode_active': 0}
2023-07-05 16:55:33.856|I|nuki.py:461|State: {'nuki_state': <NukiState.DOOR_MODE: 2>, 'lock_state': <LockState.UNLATCHING: 7>, 'trigger': 0, 'current_time': datetime.datetime(2023, 7, 5, 16, 56), 'timezone_offset': 120, 'critical_battery_state': 120, 'current_update_count': 5, 'lock_n_go_timer': 0, 'last_lock_action': <NukiAction.UNLATCH: 3>, 'last_lock_action_trigger': 0, 'last_lock_action_completion_status': 0, 'door_sensor_state': <DoorsensorState.UNAVAILABLE: 0>, 'nightmode_active': 0}
2023-07-05 16:55:33.861|I|nuki.py:461|State: {'nuki_state': <NukiState.DOOR_MODE: 2>, 'lock_state': <LockState.UNLATCHING: 7>, 'trigger': 0, 'current_time': datetime.datetime(2023, 7, 5, 16, 56), 'timezone_offset': 120, 'critical_battery_state': 120, 'current_update_count': 5, 'lock_n_go_timer': 0, 'last_lock_action': <NukiAction.UNLATCH: 3>, 'last_lock_action_trigger': 0, 'last_lock_action_completion_status': 0, 'door_sensor_state': <DoorsensorState.UNAVAILABLE: 0>, 'nightmode_active': 0}
2023-07-05 16:55:34.750|E|nuki.py:549|Error: <class 'bleak.exc.BleakDBusError'> [org.bluez.Error.InProgress] In Progress
Traceback (most recent call last):
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 547, in _send_data
    await self._client.write_gatt_char(characteristic, data)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 800, in write_gatt_char
    assert_reply(reply)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] In Progress
2023-07-05 16:55:34.809|E|nuki.py:455|Error 34
2023-07-05 16:55:34.812|I|nuki.py:590|Nuki disconnecting
2023-07-05 16:55:34.826|E|nuki.py:455|Error 34
2023-07-05 16:55:34.829|I|nuki.py:590|Nuki disconnecting
2023-07-05 16:55:34.836|E|nuki.py:455|Error 34
2023-07-05 16:55:34.838|I|nuki.py:590|Nuki disconnecting

Do you have any idea what that could be and how to fix it? As i mentioned this is not always the behaviour, sometimes it works quite fast, but sometimes the lock keeps unresponsive and shows those messages in the log

Thx in advance BR technotroll

dauden1184 commented 1 year ago

Hi, What version of bluez are you using?

techn0tr0ll commented 1 year ago

heyho Current installed version is 5.55

techn0tr0ll commented 1 year ago

hey there

Do you have any idea on this issue?

We encountered also another issue, maybe depending on each other, but not sure

2023-07-17 18:16:48.670|E|nuki.py:549|Error: <class 'bleak.exc.BleakDBusError'> [org.bluez.Error.InProgress] In ProgressTraceback (most recent call last):
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 547, in _send_data
    await self._client.write_gatt_char(characteristic, data)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 800, in write_gatt_char
    assert_reply(reply)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.InProgress] In Progress
2023-07-17 18:16:48.682|E|nuki.py:455|Error 34
2023-07-17 18:16:48.685|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.739|E|nuki.py:455|Error 34
2023-07-17 18:16:48.741|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.746|E|nuki.py:455|Error 34
2023-07-17 18:16:48.749|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.759|E|nuki.py:455|Error 34
2023-07-17 18:16:48.763|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.911|E|nuki.py:455|Error 34
2023-07-17 18:16:48.913|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.918|E|nuki.py:455|Error 34
2023-07-17 18:16:48.920|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.925|E|nuki.py:455|Error 34
2023-07-17 18:16:48.928|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:48.933|E|nuki.py:455|Error 34
2023-07-17 18:16:48.935|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:49.794|E|nuki.py:455|Error 34
2023-07-17 18:16:49.797|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:49.804|E|nuki.py:455|Error 34
2023-07-17 18:16:49.806|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:49.811|E|nuki.py:455|Error 34
2023-07-17 18:16:49.813|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:49.818|E|nuki.py:455|Error 34
2023-07-17 18:16:49.820|I|nuki.py:590|Nuki disconnecting
2023-07-17 18:16:51.158|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.177|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.200|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.220|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.239|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.259|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.278|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.298|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.318|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.337|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.359|I|nuki.py:169|Start scanning
2023-07-17 18:16:51.381|I|nuki.py:169|Start scanning
2023-07-17 18:16:55.213|I|nuki.py:598|Updating nuki state
2023-07-17 18:16:55.217|I|nuki.py:173|Stop scanning
2023-07-17 18:16:56.069|I|nuki.py:569|Nuki connecting
2023-07-17 18:16:56.801|E|nuki.py:549|Error: <class 'bleak.exc.BleakDBusError'> [org.bluez.Error.Failed] Software caused connection abort
Traceback (most recent call last):
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 543, in _send_data
    await self.connect()
  File "/home/pi/RaspiNukiBridge/./nuki.py", line 570, in connect
    await self._client.connect()
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 278, in connect
    assert_reply(reply)
  File "/home/pi/.local/lib/python3.9/site-packages/bleak/backends/bluezdbus/utils.py", line 23, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Software caused connection abort
dauden1184 commented 1 year ago

Looking at the logs and all the lines repeated 3 or 4 times (or more) at the same time it seems the lock is trying to process more than one requests at a time. The library should reply with a proper error message but right now this is not implemented.

How are you sending the requests? Is it possible that you are sending more requests at the same time?

techn0tr0ll commented 1 year ago

yep, thats also our knowledge status rn.

We've build another service, that is sending the request to the bridge (pi) and waits for a response from the bridge. In some cases, this response does not appear and nothing happens (waiting > 2 minutes)... Our service also waits for 2 minutes before it is possible to send another request .

Sending a second request even a couple of minutes later sometimes leads to this behaviour but not always ... it's really weird - thats why i asked for some input &/ experiences from your side :D

dauden1184 commented 1 year ago

Do you have any logs where it happens that you perform the request and there is no reply?

techn0tr0ll commented 1 year ago

hey there sorry for my late response... There is nothing special when it performs the action on the bridge but not on the lock

2023-07-24 16:29:45.841|I|nuki.py:625|Lock action 3
2023-07-24 16:29:45.847|I|nuki.py:173|Stop scanning
2023-07-24 16:29:46.238|I|nuki.py:569|Nuki connecting
<new request here after ~2 minutes>

The second request then looks like the logs in my initial post... a lot of error messages but the door opens