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.

Sign up for GitHub

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

Jump to bottom

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

Open
techn0tr0ll opened this issue Jul 5, 2023 · 7 comments
Open

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

techn0tr0ll opened this issue Jul 5, 2023 · 7 comments

Comments

@techn0tr0ll
Copy link

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

Hi,
What version of bluez are you using?

@techn0tr0ll
Copy link
Author

heyho
Current installed version is 5.55

@techn0tr0ll
Copy link
Author

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

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

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

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

@techn0tr0ll
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dauden1184 @techn0tr0ll