Regression in 0.18.0: Stuck on Connecting... even after closed BLE connection

[tormodvolden]

The scenario here is that smpmgr connects to the device, but because of failed pairing the SMP upload doesn't start. This device will disconnect BLE after 30 seconds if certain conditions are not met. On 0.17.0 smpmgr will exit with "Aborted." as soon as the BLE connection is dropped. On 0.18.0 smpmgr just hangs at ⠏ Connecting to ... seemingly forever (at least 10 minutes).

Also, I use --timeout 10 but that doesn't prevent the 30 s from passing on both versions, is this by design? 0.13.0 will fail already after 10 s here (0.13.1 or later won't):

[14:11:56] ERROR    Transport error: connection timeout -          common.py:97
                    common:97    

BTW, I also tried going back to smpmgr 0.9.0 which I have been using earlier, this now fails to parse arguments, which obviously worked when I had 0.9.0 before. Same up to 0.12.1. I wonder if this is due to upgraded dependencies even though I thought the Python virtual environment would take care of that. Has anyone seen this failure to parse arguments at some point?

Details

$ /tmp/test_venv9/bin/smpmgr --help
                                                                                                                                                                                                                                                              
 Usage: smpmgr [OPTIONS] COMMAND [ARGS]...                                                                                                                                                                                                                    
                                                                                                                                                                                                                                                              
 Simple Management Protocol (SMP) Manager Version 0.9.0                                                                                                                                                                                                       
 Copyright (c) 2023-2024 Intercreate, Inc. and Contributors                                                                                                                                                                                                   
                                                                                                                                                                                                                                                              
╭─────────────────────────────── Traceback (most recent call last) ────────────────────────────────╮
│ /tmp/test_venv9/bin/smpmgr:8 in <module>                                                         │
│                                                                                                  │
│   5 from smpmgr.main import app                                                                  │
│   6 if __name__ == '__main__':                                                                   │
│   7 │   sys.argv[0] = re.sub(r'(-script\.pyw|\.exe)?$', '', sys.argv[0])                         │
│ ❱ 8 │   sys.exit(app())                                                                          │
│   9                                                                                              │
│                                                                                                  │
│ ╭─────────────────────────── locals ────────────────────────────╮                                │
│ │ app = <typer.main.Typer object at 0x7376493c00b0>             │                                │
│ │  re = <module 're' from '/usr/lib/python3.12/re/__init__.py'> │                                │
│ │ sys = <module 'sys' (built-in)>                               │                                │
│ ╰───────────────────────────────────────────────────────────────╯                                │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/main.py:328 in __call__                       │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/main.py:311 in __call__                       │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:1524 in __call__                      │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/core.py:783 in main                           │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/core.py:224 in _main                          │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:1255 in make_context                  │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:1868 in parse_args                    │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:1266 in parse_args                    │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:2635 in handle_parse_result           │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:3436 in process_value                 │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:2497 in process_value                 │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/decorators.py:539 in show_help                │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:805 in get_help                       │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/click/core.py:1147 in get_help                      │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/core.py:796 in format_help                    │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/rich_utils.py:605 in rich_format_help         │
│                                                                                                  │
│ /tmp/test_venv9/lib/python3.12/site-packages/typer/rich_utils.py:370 in _print_options_panel     │
╰──────────────────────────────────────────────────────────────────────────────────────────────────╯
TypeError: Parameter.make_metavar() missing 1 required positional argument: 'ctx'

[JPHutchins]

Thanks! For 0.18.0, can you enable the DEBUG logging via stdout or file, and paste or upload the results here?

This should tell us where it's left off. The trace after using Ctrl-C is also helpful.

[tormodvolden]

When I press ctrl-C there is no output. Here is a debug log attached (UUIDs stripped to protect the innocent somewhat).

smpmgr18.log

[JPHutchins]

Thanks for the debug log — that was enough to pin it down. The hang is in SMPBLETransport.connect(): await BleakClient.start_notify(...) never returns once the peer disconnects mid-pairing, because the BlueZ StartNotify D-Bus call doesn't get a reply when the peer goes away. The --timeout being ignored is the same flow — timeout_s was only threaded into the initial scan, not the rest of connect.

Tracking the smpclient-side fix in intercreate/smpclient#108:

• Wraps the whole connect() in asyncio.wait_for(timeout=timeout_s) so --timeout 10 actually fires after 10 s when the peer hangs.
• Races start_notify against the disconnect event and raises SMPTransportDisconnected instead of hanging.
• Pins bleak>=3.0.2,<4 (the bleak 2.0.x line has its own separate AcquireNotify hang regression — see hbldh/bleak#1885).

Once that merges and an smpclient release is published, I'll open a follow-up PR here bumping the smpclient pin and we can close this issue then.

(The 0.9.0 traceback you saw is unrelated — that's a separate typer/click compatibility break from a newer click changing Parameter.make_metavar()'s signature in a way the old typer pinned in 0.9.0's venv can't handle. Out of scope for this fix.)