2023-05-21 15:32:16

by Pauli Virtanen

[permalink] [raw]
Subject: [PATCH BlueZ 1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG

There is a race between multiple connect() for CIS in the same CIG.
connect() will both reconfigure the CIG and connect the CIS, but CIG
cannot be reconfigured once one CIS has already connected. That these
tests pass currently relies on some timing/event ordering in the
emulator.

Connecting multiple CIS in same CIG is meant to be done using
DEFER_SETUP, so change the tests to use it, so we test the intended
usage.
---
tools/iso-tester.c | 150 +++++++++++++++++++++++++++++++--------------
1 file changed, 104 insertions(+), 46 deletions(-)

diff --git a/tools/iso-tester.c b/tools/iso-tester.c
index c5c6f0aec..164cb465f 100644
--- a/tools/iso-tester.c
+++ b/tools/iso-tester.c
@@ -740,6 +740,12 @@ static const struct iso_client_data defer_16_2_1 = {
.defer = true,
};

+static const struct iso_client_data defer_1_16_2_1 = {
+ .qos = QOS_1_16_2_1,
+ .expect_err = 0,
+ .defer = true,
+};
+
static const struct iso_client_data connect_16_2_1_defer_send = {
.qos = QOS_16_2_1,
.expect_err = 0,
@@ -817,6 +823,7 @@ static const struct iso_client_data connect_ac_6i = {
.qos_2 = AC_6i_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_6ii = {
@@ -824,6 +831,7 @@ static const struct iso_client_data connect_ac_6ii = {
.qos_2 = AC_6ii_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_7i = {
@@ -831,6 +839,7 @@ static const struct iso_client_data connect_ac_7i = {
.qos_2 = AC_7i_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_7ii = {
@@ -838,6 +847,7 @@ static const struct iso_client_data connect_ac_7ii = {
.qos_2 = AC_7ii_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_8i = {
@@ -845,6 +855,7 @@ static const struct iso_client_data connect_ac_8i = {
.qos_2 = AC_8i_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_8ii = {
@@ -852,6 +863,7 @@ static const struct iso_client_data connect_ac_8ii = {
.qos_2 = AC_8ii_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_9i = {
@@ -859,6 +871,7 @@ static const struct iso_client_data connect_ac_9i = {
.qos_2 = AC_9i_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_9ii = {
@@ -866,6 +879,7 @@ static const struct iso_client_data connect_ac_9ii = {
.qos_2 = AC_9ii_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_11i = {
@@ -873,6 +887,7 @@ static const struct iso_client_data connect_ac_11i = {
.qos_2 = AC_11i_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data connect_ac_11ii = {
@@ -880,6 +895,7 @@ static const struct iso_client_data connect_ac_11ii = {
.qos_2 = AC_11ii_2,
.expect_err = 0,
.mcis = true,
+ .defer = true,
};

static const struct iso_client_data bcast_16_2_1_send = {
@@ -1715,13 +1731,9 @@ static gboolean iso_connect2_cb(GIOChannel *io, GIOCondition cond,
return iso_connect(io, cond, user_data);
}

-static void setup_connect(struct test_data *data, uint8_t num, GIOFunc func)
+static int setup_sock(struct test_data *data, uint8_t num)
{
- const struct iso_client_data *isodata = data->test_data;
- GIOChannel *io;
int sk, err;
- char c;
- struct pollfd pfd;

sk = create_iso_sock(data);
if (sk < 0) {
@@ -1729,7 +1741,8 @@ static void setup_connect(struct test_data *data, uint8_t num, GIOFunc func)
tester_test_abort();
else
tester_test_failed();
- return;
+
+ return sk;
}

err = connect_iso_sock(data, num, sk);
@@ -1743,65 +1756,106 @@ static void setup_connect(struct test_data *data, uint8_t num, GIOFunc func)
else
tester_test_failed();

- return;
+ return err;
}

- if (isodata->defer) {
- int defer;
- socklen_t len;
-
- /* Check if socket has DEFER_SETUP set */
- len = sizeof(defer);
- if (getsockopt(sk, SOL_BLUETOOTH, BT_DEFER_SETUP, &defer,
- &len) < 0) {
- tester_warn("getsockopt: %s (%d)", strerror(errno),
- errno);
+ return sk;
+}
+
+static int connect_deferred(int sk)
+{
+ int defer;
+ socklen_t len;
+ struct pollfd pfd;
+ char c;
+
+ /* Check if socket has DEFER_SETUP set */
+ len = sizeof(defer);
+ if (getsockopt(sk, SOL_BLUETOOTH, BT_DEFER_SETUP, &defer,
+ &len) < 0) {
+ tester_warn("getsockopt: %s (%d)", strerror(errno),
+ errno);
+ tester_test_failed();
+ return 0;
+ }
+
+ memset(&pfd, 0, sizeof(pfd));
+ pfd.fd = sk;
+ pfd.events = POLLOUT;
+
+ if (poll(&pfd, 1, 0) < 0) {
+ tester_warn("poll: %s (%d)", strerror(errno), errno);
+ tester_test_failed();
+ return -EIO;
+ }
+
+ if (!(pfd.revents & POLLOUT)) {
+ if (read(sk, &c, 1) < 0) {
+ tester_warn("read: %s (%d)", strerror(errno),
+ errno);
tester_test_failed();
- return;
+ return -EIO;
}
+ }
+
+ return 0;
+}

- memset(&pfd, 0, sizeof(pfd));
- pfd.fd = sk;
- pfd.events = POLLOUT;
+static void setup_connect_many(struct test_data *data, uint8_t n, uint8_t *num,
+ GIOFunc *func)
+{
+ const struct iso_client_data *isodata = data->test_data;
+ int sk[256];
+ GIOChannel *io;
+ unsigned int i;

- if (poll(&pfd, 1, 0) < 0) {
- tester_warn("poll: %s (%d)", strerror(errno), errno);
- tester_test_failed();
+ for (i = 0; i < n; ++i) {
+ sk[i] = setup_sock(data, num[i]);
+ if (sk[i] < 0)
return;
- }
+ }

- if (!(pfd.revents & POLLOUT)) {
- if (read(sk, &c, 1) < 0) {
- tester_warn("read: %s (%d)", strerror(errno),
- errno);
- tester_test_failed();
+ if (isodata->defer) {
+ for (i = 0; i < n; ++i)
+ if (connect_deferred(sk[i]) < 0)
return;
- }
- }
}

- io = g_io_channel_unix_new(sk);
- g_io_channel_set_close_on_unref(io, TRUE);
+ for (i = 0; i < n; ++i) {
+ io = g_io_channel_unix_new(sk[i]);
+ g_io_channel_set_close_on_unref(io, TRUE);

- data->io_id[num] = g_io_add_watch(io, G_IO_OUT, func, NULL);
+ data->io_id[num[i]] = g_io_add_watch(io, G_IO_OUT, func[i],
+ NULL);

- g_io_channel_unref(io);
+ g_io_channel_unref(io);

- tester_print("Connect in progress");
+ tester_print("Connect %d in progress", num[i]);

- data->step++;
+ data->step++;
+ }
+}
+
+static void setup_connect(struct test_data *data, uint8_t num, GIOFunc func)
+{
+ return setup_connect_many(data, 1, &num, &func);
}

static void test_connect(const void *test_data)
{
struct test_data *data = tester_get_data();
const struct iso_client_data *isodata = test_data;
+ uint8_t n = 0;
+ GIOFunc func[2];
+ uint8_t num[2] = {0, 1};

- setup_connect(data, 0, iso_connect_cb);
+ func[n++] = iso_connect_cb;

/* Check if configuration requires multiple CIS setup */
if (!isodata->bcast && isodata->mcis)
- setup_connect(data, 1, iso_connect2_cb);
+ func[n++] = iso_connect2_cb;
+
+ setup_connect_many(data, n, num, func);
}

static void setup_reconnect(struct test_data *data, uint8_t num, GIOFunc func)
@@ -2066,9 +2120,10 @@ static void test_listen(const void *test_data)
static void test_connect2(const void *test_data)
{
struct test_data *data = tester_get_data();
+ uint8_t num[2] = {0, 1};
+ GIOFunc funcs[2] = {iso_connect_cb, iso_connect2_cb};

- setup_connect(data, 0, iso_connect_cb);
- setup_connect(data, 1, iso_connect2_cb);
+ setup_connect_many(data, 2, num, funcs);
}

static void test_bcast(const void *test_data)
@@ -2212,10 +2267,6 @@ int main(int argc, char *argv[])
test_iso_rej("ISO Connect - Reject", &connect_reject, setup_powered,
test_connect, BT_HCI_ERR_CONN_FAILED_TO_ESTABLISH);

- test_iso2("ISO Connect2 CIG 0x01 - Success", &connect_1_16_2_1,
- setup_powered,
- test_connect2);
-
test_iso("ISO Send - Success", &connect_16_2_1_send, setup_powered,
test_connect);

@@ -2229,6 +2280,13 @@ int main(int argc, char *argv[])
test_iso("ISO Defer - Success", &defer_16_2_1, setup_powered,
test_defer);

+ test_iso("ISO Defer Connect - Success", &defer_16_2_1, setup_powered,
+ test_connect);
+
+ test_iso2("ISO Defer Connect2 CIG 0x01 - Success", &defer_1_16_2_1,
+ setup_powered,
+ test_connect2);
+
test_iso("ISO Defer Send - Success", &connect_16_2_1_defer_send,
setup_powered,
test_connect);
--
2.40.1



2023-05-21 15:32:36

by Pauli Virtanen

[permalink] [raw]
Subject: [PATCH BlueZ 3/5] btdev: support multiple CIG

Add support for more than one CIG simultaneously.
---
emulator/btdev.c | 144 +++++++++++++++++++++++++++++++++++------------
1 file changed, 108 insertions(+), 36 deletions(-)

diff --git a/emulator/btdev.c b/emulator/btdev.c
index 7980a5280..0eec1d9f2 100644
--- a/emulator/btdev.c
+++ b/emulator/btdev.c
@@ -42,6 +42,7 @@
#define RL_SIZE 16
#define CIS_SIZE 3
#define BIS_SIZE 3
+#define CIG_SIZE 3

#define has_bredr(btdev) (!((btdev)->features[4] & 0x20))
#define has_le(btdev) (!!((btdev)->features[4] & 0x40))
@@ -101,6 +102,11 @@ struct le_ext_adv {
unsigned int id;
};

+struct le_cig {
+ struct bt_hci_cmd_le_set_cig_params params;
+ struct bt_hci_cis_params cis[CIS_SIZE];
+} __attribute__ ((packed));
+
struct btdev {
enum btdev_type type;
uint16_t id;
@@ -204,10 +210,7 @@ struct btdev {
uint16_t le_pa_sync_handle;
uint8_t big_handle;
uint8_t le_ltk[16];
- struct {
- struct bt_hci_cmd_le_set_cig_params params;
- struct bt_hci_cis_params cis[CIS_SIZE];
- } __attribute__ ((packed)) le_cig;
+ struct le_cig le_cig[CIG_SIZE];
uint8_t le_iso_path[2];

/* Real time length of AL array */
@@ -5757,6 +5760,36 @@ static int cmd_read_iso_tx_sync(struct btdev *dev, const void *data,
return -ENOTSUP;
}

+static int find_cig(struct btdev *dev, uint8_t cig_id)
+{
+ unsigned int i;
+
+ for (i = 0; i < ARRAY_SIZE(dev->le_cig); ++i)
+ if (dev->le_cig[i].params.cig_id == cig_id)
+ return i;
+ return -1;
+}
+
+static uint16_t make_cis_handle(uint8_t cig_idx, uint8_t cis_idx)
+{
+ /* Put CIG+CIS idxs to handle so don't need to track separately */
+ return ISO_HANDLE + cig_idx*CIS_SIZE + cis_idx;
+}
+
+static int parse_cis_handle(uint16_t handle, int *cis_idx)
+{
+ int cig_idx;
+
+ if (handle < ISO_HANDLE || handle >= ISO_HANDLE + CIS_SIZE*CIG_SIZE)
+ return -1;
+
+ cig_idx = (handle - ISO_HANDLE) / CIS_SIZE;
+ if (cis_idx)
+ *cis_idx = (handle - ISO_HANDLE) % CIS_SIZE;
+
+ return cig_idx;
+}
+
static int cmd_set_cig_params(struct btdev *dev, const void *data,
uint8_t len)
{
@@ -5766,12 +5799,13 @@ static int cmd_set_cig_params(struct btdev *dev, const void *data,
uint16_t handle[CIS_SIZE];
} __attribute__ ((packed)) rsp;
int i = 0;
+ int cig_idx;
uint32_t interval;
uint16_t latency;

memset(&rsp, 0, sizeof(rsp));

- if (cmd->num_cis > ARRAY_SIZE(dev->le_cig.cis)) {
+ if (cmd->num_cis > ARRAY_SIZE(dev->le_cig[0].cis)) {
rsp.params.status = BT_HCI_ERR_MEM_CAPACITY_EXCEEDED;
goto done;
}
@@ -5820,14 +5854,14 @@ static int cmd_set_cig_params(struct btdev *dev, const void *data,
goto done;
}

- if (dev->le_cig.params.cig_id != 0xff &&
- dev->le_cig.params.cig_id != cmd->cig_id) {
- rsp.params.status = BT_HCI_ERR_INVALID_PARAMETERS;
+ cig_idx = find_cig(dev, cmd->cig_id);
+ if (cig_idx < 0)
+ cig_idx = find_cig(dev, 0xff);
+ if (cig_idx < 0) {
+ rsp.params.status = BT_HCI_ERR_MEM_CAPACITY_EXCEEDED;
goto done;
}

- memcpy(&dev->le_cig, data, len);
-
rsp.params.status = BT_HCI_ERR_SUCCESS;
rsp.params.cig_id = cmd->cig_id;

@@ -5835,7 +5869,7 @@ static int cmd_set_cig_params(struct btdev *dev, const void *data,
struct btdev_conn *iso;

rsp.params.num_handles++;
- rsp.handle[i] = cpu_to_le16(ISO_HANDLE + i);
+ rsp.handle[i] = cpu_to_le16(make_cis_handle(cig_idx, i));

/* BLUETOOTH CORE SPECIFICATION Version 5.3 | Vol 4, Part E
* page 2553
@@ -5845,14 +5879,16 @@ static int cmd_set_cig_params(struct btdev *dev, const void *data,
* code Command Disallowed (0x0C).
*/
iso = queue_find(dev->conns, match_handle,
- UINT_TO_PTR(cpu_to_le16(rsp.handle[i])));
+ UINT_TO_PTR(le16_to_cpu(rsp.handle[i])));
if (iso) {
- rsp.params.status = BT_HCI_ERR_INVALID_PARAMETERS;
+ rsp.params.status = BT_HCI_ERR_COMMAND_DISALLOWED;
i = 0;
goto done;
}
}

+ memcpy(&dev->le_cig[cig_idx], data, len);
+
done:
cmd_complete(dev, BT_HCI_CMD_LE_SET_CIG_PARAMS, &rsp,
sizeof(rsp.params) + (i * sizeof(uint16_t)));
@@ -5878,35 +5914,40 @@ static void le_cis_estabilished(struct btdev *dev, struct btdev_conn *conn,
uint8_t status)
{
struct bt_hci_evt_le_cis_established evt;
+ int cig_idx, cis_idx;

memset(&evt, 0, sizeof(evt));

evt.status = status;
evt.conn_handle = conn ? cpu_to_le16(conn->handle) : 0x0000;

+ cig_idx = conn ? parse_cis_handle(conn->link->handle, &cis_idx) : -1;
+ if (cig_idx < 0 && !evt.status)
+ evt.status = BT_HCI_ERR_UNSPECIFIED_ERROR;
+
if (!evt.status) {
struct btdev *remote = conn->link->dev;
- int i = conn->handle - ISO_HANDLE;
+ struct le_cig *le_cig = &remote->le_cig[cig_idx];

/* TODO: Figure out if these values makes sense */
- memcpy(evt.cig_sync_delay, remote->le_cig.params.c_interval,
- sizeof(remote->le_cig.params.c_interval));
- memcpy(evt.cis_sync_delay, remote->le_cig.params.p_interval,
- sizeof(remote->le_cig.params.p_interval));
- memcpy(evt.c_latency, &remote->le_cig.params.c_interval,
- sizeof(remote->le_cig.params.c_interval));
- memcpy(evt.p_latency, &remote->le_cig.params.p_interval,
- sizeof(remote->le_cig.params.p_interval));
- evt.c_phy = remote->le_cig.cis[i].c_phy;
- evt.p_phy = remote->le_cig.cis[i].p_phy;
+ memcpy(evt.cig_sync_delay, le_cig->params.c_interval,
+ sizeof(le_cig->params.c_interval));
+ memcpy(evt.cis_sync_delay, le_cig->params.p_interval,
+ sizeof(le_cig->params.p_interval));
+ memcpy(evt.c_latency, &le_cig->params.c_interval,
+ sizeof(le_cig->params.c_interval));
+ memcpy(evt.p_latency, &le_cig->params.p_interval,
+ sizeof(le_cig->params.p_interval));
+ evt.c_phy = le_cig->cis[cis_idx].c_phy;
+ evt.p_phy = le_cig->cis[cis_idx].p_phy;
evt.nse = 0x01;
evt.c_bn = 0x01;
evt.p_bn = 0x01;
evt.c_ft = 0x01;
evt.p_ft = 0x01;
- evt.c_mtu = remote->le_cig.cis[i].c_sdu;
- evt.p_mtu = remote->le_cig.cis[i].p_sdu;
- evt.interval = remote->le_cig.params.c_latency;
+ evt.c_mtu = le_cig->cis[cis_idx].c_sdu;
+ evt.p_mtu = le_cig->cis[cis_idx].p_sdu;
+ evt.interval = le_cig->params.c_latency;
}

le_meta_event(dev, BT_HCI_EVT_LE_CIS_ESTABLISHED, &evt, sizeof(evt));
@@ -5927,9 +5968,20 @@ static int cmd_create_cis_complete(struct btdev *dev, const void *data,
struct btdev_conn *acl;
struct btdev_conn *iso;
struct bt_hci_evt_le_cis_req evt;
+ struct le_cig *le_cig;
+ int cig_idx, cis_idx;
+
+ cig_idx = parse_cis_handle(le16_to_cpu(cis->cis_handle),
+ &cis_idx);
+ if (cig_idx < 0) {
+ le_cis_estabilished(dev, NULL,
+ BT_HCI_ERR_UNKNOWN_CONN_ID);
+ break;
+ }
+ le_cig = &dev->le_cig[cig_idx];

acl = queue_find(dev->conns, match_handle,
- UINT_TO_PTR(cpu_to_le16(cis->acl_handle)));
+ UINT_TO_PTR(le16_to_cpu(cis->acl_handle)));
if (!acl) {
le_cis_estabilished(dev, NULL,
BT_HCI_ERR_UNKNOWN_CONN_ID);
@@ -5937,9 +5989,9 @@ static int cmd_create_cis_complete(struct btdev *dev, const void *data,
}

iso = queue_find(dev->conns, match_handle,
- UINT_TO_PTR(cpu_to_le16(cis->cis_handle)));
+ UINT_TO_PTR(le16_to_cpu(cis->cis_handle)));
if (!iso) {
- iso = conn_add_cis(acl, cpu_to_le16(cis->cis_handle));
+ iso = conn_add_cis(acl, le16_to_cpu(cis->cis_handle));
if (!iso) {
le_cis_estabilished(dev, NULL,
BT_HCI_ERR_UNKNOWN_CONN_ID);
@@ -5949,8 +6001,8 @@ static int cmd_create_cis_complete(struct btdev *dev, const void *data,

evt.acl_handle = cpu_to_le16(acl->handle);
evt.cis_handle = cpu_to_le16(iso->handle);
- evt.cig_id = iso->dev->le_cig.params.cig_id;
- evt.cis_id = iso->dev->le_cig.cis[i].cis_id;
+ evt.cig_id = le_cig->params.cig_id;
+ evt.cis_id = le_cig->cis[cis_idx].cis_id;

le_meta_event(iso->link->dev, BT_HCI_EVT_LE_CIS_REQ, &evt,
sizeof(evt));
@@ -5959,20 +6011,37 @@ static int cmd_create_cis_complete(struct btdev *dev, const void *data,
return 0;
}

+static bool match_handle_cig_idx(const void *data, const void *match_data)
+{
+ const struct btdev_conn *conn = data;
+ int cig_idx = PTR_TO_INT(match_data);
+
+ return cig_idx >= 0 && parse_cis_handle(conn->handle, NULL) == cig_idx;
+}
+
static int cmd_remove_cig(struct btdev *dev, const void *data, uint8_t len)
{
const struct bt_hci_cmd_le_remove_cig *cmd = data;
struct bt_hci_rsp_le_remove_cig rsp;
+ struct btdev_conn *conn = NULL;
+ int idx;

- memset(&dev->le_cig, 0, sizeof(dev->le_cig));
memset(&rsp, 0, sizeof(rsp));

rsp.cig_id = cmd->cig_id;

- if (dev->le_cig.params.cig_id == cmd->cig_id)
+ idx = find_cig(dev, cmd->cig_id);
+ conn = queue_find(dev->conns, match_handle_cig_idx, INT_TO_PTR(idx));
+
+ if (idx >= 0 && !conn) {
+ memset(&dev->le_cig[idx], 0, sizeof(struct le_cig));
+ dev->le_cig[idx].params.cig_id = 0xff;
rsp.status = BT_HCI_ERR_SUCCESS;
- else
+ } else if (conn) {
+ rsp.status = BT_HCI_ERR_COMMAND_DISALLOWED;
+ } else {
rsp.status = BT_HCI_ERR_UNKNOWN_CONN_ID;
+ }

cmd_complete(dev, BT_HCI_CMD_LE_REMOVE_CIG, &rsp, sizeof(rsp));

@@ -6842,6 +6911,7 @@ struct btdev *btdev_create(enum btdev_type type, uint16_t id)
{
struct btdev *btdev;
int index;
+ unsigned int i;

btdev = malloc(sizeof(*btdev));
if (!btdev)
@@ -6909,9 +6979,11 @@ struct btdev *btdev_create(enum btdev_type type, uint16_t id)

btdev->iso_mtu = 251;
btdev->iso_max_pkt = 1;
- btdev->le_cig.params.cig_id = 0xff;
btdev->big_handle = 0xff;

+ for (i = 0; i < ARRAY_SIZE(btdev->le_cig); ++i)
+ btdev->le_cig[i].params.cig_id = 0xff;
+
btdev->country_code = 0x00;

index = add_btdev(btdev);
--
2.40.1


2023-05-21 16:17:47

by Pauli Virtanen

[permalink] [raw]
Subject: hci_sync req_complete_skb does not get called?

The patch below adds variants of multi-CIG connection tests to BlueZ
iso-tester that connect them at the same time instead of sequentially.

In test-runner, the test

ISO Connect2 CIG 0x01/0x02 - Success

appears to time out on bluetooth-next/master, as a LE Extended Create
Connection command gets a timeout.

This seems to be because hci_le_ext_create_conn_sync waits for
HCI_LE_Enhanced_Connection_Complete, and things go wrong:

The controller emits HCI_Command_Status first.

Then, kernel queues another command (Disconnect), before the
Connection_Complete event that hci_le_ext_create_conn_sync waits for
arrives.

This replaces hdev->sent_cmd in hci_cmd_work. Because of this, when the
Create_Connection event arrives, hci_cmd_sync_complete for the Create
Connection command won't be called. As a result, creating the connection
hangs until hci_sync timeout.

This looks like timing-sensitive issue in the hci_request/hci_sync
logic: the req_complete* callback for a request will not be called if
another command gets sent while the request waits for an event.

This seems to block the hci_sync queue for a while, so it probably is
not intended behavior?

Example trace from

./tools/iso-tester -d -s "ISO Connect2 CIG 0x01/0x02 - Success"

and for kernel with enabled debug prints:

> __hci_cmd_sync_sk:154: hci0: Opcode 0x2043
> hci_cmd_sync_add:88: hci0: opcode 0x2043 plen 58
> hci_cmd_sync_alloc:66: hci0: skb len 61
> hci_cmd_sync_run:118: hci0: length 1
> hci_cmd_work:4092: hci0 cmd_cnt 1 cmd queued 1
> hci_send_frame:2982: hci0 type 1 len 61
> Successfully connected
> Step 1
> hci_conn_drop:1416: hcon ffff888001933000 orig refcnt 1
> hci_send_cmd:3020: hci0 opcode 0x0406 plen 3
> hci_cmd_work:4092: hci0 cmd_cnt 0 cmd queued 1

Here, HCI_Disconnect (0x0406) got queued while
HCI_LE_Extended_Create_Connection (0x2043) sync request is waiting for
HCI_LE_Enhanced_Connection_Complete (0x0a). The disconnect cmd is not sent
yet, as there's no room in cmd_cnt.

> hciemu: vhci: > 01 43 20 3a 00 00 00 01 00 02 01 aa 00 07 60 00 .C :..........`.
> hciemu: vhci: 60 00 18 00 28 00 00 00 2a 00 00 00 00 00 60 00 `...(...*.....`.
> hciemu: vhci: 60 00 18 00 28 00 00 00 2a 00 00 00 00 00 60 00 `...(...*.....`.
> hciemu: vhci: 60 00 18 00 28 00 00 00 2a 00 00 00 00 00 `...(...*.....
> hciemu: vhci: command 0x2043
> hciemu: vhci: event 0x0f opcode 0x2043
> hciemu: vhci: < 04 .
> hciemu: vhci: 0f 04 ..
> hciemu: vhci: 00 01 43 20 ..C
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x0f
> hci_cmd_status_evt:4291: hci0: opcode 0x2043
> hci_cs_le_ext_create_conn:2910: hci0: status 0x00
> hci_sent_cmd_data:3083: hci0 opcode 0x2043

The HCI_LE_Extended_Create_Connection command status event arrived. The
hci_sync request is waiting for a different event, so the status event didn't
complete it.

hci_cmd_status_evt makes room in cmd_cnt and queues cmd_work.

> hci_cmd_work:4092: hci0 cmd_cnt 1 cmd queued 1
> hci_send_frame:2982: hci0 type 1 len 6

The queued HCI_Disconnect was sent to the driver. At this point hdev->sent_cmd
is replaced by the skb of the HCI_Disconnect, and the completion callback of
the HCI_LE_Extended_Create_Connection sync request will never be called.

> hciemu: vhci: conn1 0x46c340 handle 0x002b
> hciemu: vhci: conn2 0x46d410 handle 0x002a
> hciemu: btdev: meta event 0x0a
> hciemu: btdev: event 0x3e
> hciemu: btdev: < 04 .
> hciemu: btdev: 3e 1f >.
> hciemu: btdev: 0a 00 2b 00 01 00 00 00 00 01 aa 00 00 00 00 00 ..+.............
> hciemu: btdev: 00 00 00 00 00 00 00 00 28 00 00 00 2a 00 00 ........(...*..
> hciemu: btdev: meta event 0x12
> hciemu: btdev: event 0x3e
> hciemu: btdev: < 04 .
> hciemu: btdev: 3e 06 >.
> hciemu: btdev: 12 00 01 2b 00 00 ...+..
> hciemu: vhci: meta event 0x0a
> hciemu: vhci: event 0x3e
> hciemu: vhci: < 04 .
> hciemu: vhci: 3e 1f >.
> hciemu: vhci: 0a 00 2b 00 00 00 01 00 02 01 aa 00 00 00 00 00 ..+.............
> hciemu: vhci: 00 00 00 00 00 00 00 00 28 00 00 00 2a 00 00 ........(...*..
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x3e
> hci_le_meta_evt:7112: hci0: subevent 0x0a
> hci_le_enh_conn_complete_evt:5988: hci0: status 0x00

Here the Connection Complete event (0x0a) arrives, but hci_req_cmd_complete and
hci_cmd_sync_complete are not called.

Some time passes without hci_sync activity:

> hci_dev_hold:1460: hci0 orig refcnt 16
> hci_send_cmd:3020: hci0 opcode 0x2016 plen 2
> hci_conn_hold:1406: hcon ffff888001935000 orig refcnt 1
> hci_cmd_work:4092: hci0 cmd_cnt 0 cmd queued 1
> hci_dev_hold:1460: hci0 orig refcnt 16
> hci_send_cmd:3020: hci0 opcode 0x2016 plen 2
> hci_conn_hold:1406: hcon ffff888001935000 orig refcnt 1
> hci_cmd_work:4092: hci0 cmd_cnt 0 cmd queued 1
> hciemu: vhci: meta event 0x12
> hciemu: vhci: event 0x3e
> hciemu: vhci: < 04 .
> hciemu: vhci: 3e 06 >.
> hciemu: vhci: 12 00 00 2b 00 00 ...+..
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x3e
> hci_le_meta_evt:7112: hci0: subevent 0x12
> hci_le_ext_adv_term_evt:6004: hci0: status 0x00
> mgmt: src/shared/mgmt.c:can_read_data() [0x0000] event 0x000b
> hciemu: vhci: > 01 06 04 03 01 01 13 .......
> hciemu: vhci: command 0x0406
> hciemu: vhci: event 0x0f opcode 0x0406
> hciemu: vhci: < 04 .
> hciemu: vhci: 0f 04 ..
> hciemu: vhci: 00 01 06 04 ....
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x0f
> hci_cmd_status_evt:4291: hci0: opcode 0x0406
> hci_cs_disconnect:2760: hci0: status 0x00
> hci_req_cmd_complete:3954: opcode 0x0406 status 0x00
> hci_sent_cmd_data:3083: hci0 opcode 0x0406
> hci_cmd_work:4092: hci0 cmd_cnt 1 cmd queued 1
> hci_send_frame:2982: hci0 type 1 len 5
> hciemu: vhci: event 0x05
> hciemu: vhci: < 04 .
> hciemu: vhci: 05 04 ..
> hciemu: vhci: 00 01 01 16 ....
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x05
> hci_disconn_complete_evt:3383: hci0: status 0x00
> hciemu: btdev: event 0x05
> hciemu: btdev: < 04 .
> hciemu: btdev: 05 04 ..
> hciemu: btdev: 00 01 01 13 ....
> hciemu: bthost: > 04 3e 1f 0a 00 2b 00 01 00 00 00 00 01 aa 00 00 .>...+..........
> hciemu: bthost: 00 00 00 00 00 00 00 00 00 00 00 28 00 00 00 2a ...........(...*
> hciemu: bthost: 00 00 ..
> hciemu: bthost: event 0x3e
> hciemu: bthost: meta event 0x0a
> hciemu: bthost: ia 00:AA:01:00:00:00 type 0x01 ra 00:AA:01:02:00:01 type 0x01
> hci_conn_drop:1416: hcon ffff888001932000 orig refcnt 1
> hciemu: vhci: > 01 16 20 02 2b 00 .. .+.
> hciemu: vhci: command 0x2016
> hciemu: vhci: event 0x0f opcode 0x2016
> hciemu: vhci: < 04 .
> hciemu: vhci: 0f 04 ..
> hciemu: vhci: 00 01 16 20 ...
> hciemu: vhci: meta event 0x04
> hciemu: vhci: event 0x3e
> hciemu: vhci: < 04 .
> hciemu: vhci: 3e 0c >.
> hci_dev_put:1452: hci0 orig refcnt 15
> hci_dev_put:1452: hci0 orig refcnt 14
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x0f
> hci_cmd_status_evt:4291: hci0: opcode 0x2016
> hci_cs_le_read_remote_features:2936: hci0: status 0x00
> hci_req_cmd_complete:3954: opcode 0x2016 status 0x00
> hci_sent_cmd_data:3083: hci0 opcode 0x2016
> hci_rx_work:4017: hci0
> hciemu: vhci: 04 00 2b 00 40 39 00 f0 01 00 00 00 ..+.@9......
> hci_rx_work:4017: hci0
> hci_rx_work:4061: hci0 Event packet
> hci_event_packet:7527: hci0: event 0x3e
> hci_le_meta_evt:7112: hci0: subevent 0x04
> hci_le_remote_feat_complete_evt:6555: hci0: status 0x00
> hci_conn_drop:1416: hcon ffff888001935000 orig refcnt 2
> hciemu: bthost: > 04 05 04 00 01 01 13 .......
> hciemu: bthost: event 0x05
> hciemu: bthost: > 04 3e 06 12 00 01 2b 00 00 .>....+..
> hciemu: bthost: event 0x3e
> hciemu: bthost: meta event 0x12
> hciemu: bthost: Unsupported LE Meta event 0x12
> ISO Connect2 CIG 0x01/0x02 - Success - teardown
> hci_unregister_dev:2687: ffff888001928000 name hci0 bus 0
> hci_send_cmd:3020: hci0 opcode 0x0406 plen 3
> hci_cmd_work:4092: hci0 cmd_cnt 1 cmd queued 1
> hci_send_frame:2982: hci0 type 1 len 6
> Bluetooth: hci0: command 0x0406 tx timeout
> hci_cmd_work:4092: hci0 cmd_cnt 1 cmd queued 0
> __hci_cmd_sync_sk:192: hci0: end: err -110
> __hci_cmd_sync_sk:154: hci0: Opcode 0x200e

... until hci_sync timeout for the LE Create Connection connection is
reached, and it tries to send LE Create Connection Cancel to cancel the
operation even though it succeeded.

Then things start to go wrong and the test ultimately hangs, as the
emulator gets torn down due to timeout at a bad time. Increasing the
test timeout makes it pass after 6sec, but not clear if this can cause
problems on a real controller.

---
tools/iso-tester.c | 8 ++++++++
1 file changed, 8 insertions(+)

diff --git a/tools/iso-tester.c b/tools/iso-tester.c
index fc2a84215..840e53e6b 100644
--- a/tools/iso-tester.c
+++ b/tools/iso-tester.c
@@ -2303,6 +2303,14 @@ int main(int argc, char *argv[])
test_iso("ISO QoS - Invalid", &connect_invalid, setup_powered,
test_connect);

+ test_iso2("ISO Connect2 CIG 0x01/0x02 - Success", &connect_2_16_2_1,
+ setup_powered,
+ test_connect2);
+
+ test_iso2("ISO Connect2 CIG auto/auto - Success", &connect_2a_16_2_1,
+ setup_powered,
+ test_connect2);
+
test_iso2("ISO Connect2 CIG 0x01/0x02 Seq - Success", &connect_2_16_2_1,
setup_powered,
test_connect2_seq);
--
2.40.1


2023-05-21 17:30:47

by bluez.test.bot

[permalink] [raw]
Subject: RE: hci_sync req_complete_skb does not get called?

This is an automated email and please do not reply to this email.

Dear Submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
While preparing the CI tests, the patches you submitted couldn't be applied to the current HEAD of the repository.

----- Output -----

error: patch failed: tools/iso-tester.c:2303
error: tools/iso-tester.c: patch does not apply
hint: Use 'git am --show-current-patch' to see the failed patch

Please resolve the issue and submit the patches again.


---
Regards,
Linux Bluetooth

2023-05-21 18:29:51

by bluez.test.bot

[permalink] [raw]
Subject: RE: [BlueZ,1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG

This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=749544

---Test result---

Test Summary:
CheckPatch FAIL 3.27 seconds
GitLint FAIL 2.14 seconds
BuildEll PASS 35.87 seconds
BluezMake PASS 1238.75 seconds
MakeCheck PASS 13.36 seconds
MakeDistcheck PASS 202.49 seconds
CheckValgrind PASS 329.93 seconds
CheckSmatch WARNING 459.17 seconds
bluezmakeextell PASS 136.68 seconds
IncrementalBuild PASS 5329.21 seconds
ScanBuild WARNING 1454.33 seconds

Details
##############################
Test: CheckPatch - FAIL
Desc: Run checkpatch.pl script
Output:
[BlueZ,3/5] btdev: support multiple CIG
WARNING:PREFER_DEFINED_ATTRIBUTE_MACRO: Prefer __packed over __attribute__((packed))
#74: FILE: emulator/btdev.c:108:
+} __attribute__ ((packed));

/github/workspace/src/src/13249428.patch total: 0 errors, 1 warnings, 279 lines checked

NOTE: For some of the reported defects, checkpatch may be able to
mechanically convert to the typical style using --fix or --fix-inplace.

/github/workspace/src/src/13249428.patch has style problems, please review.

NOTE: Ignored message types: COMMIT_MESSAGE COMPLEX_MACRO CONST_STRUCT FILE_PATH_CHANGES MISSING_SIGN_OFF PREFER_PACKED SPDX_LICENSE_TAG SPLIT_STRING SSCANF_TO_KSTRTO

NOTE: If any of the errors are false positives, please report
them to the maintainer, see CHECKPATCH in MAINTAINERS.


##############################
Test: GitLint - FAIL
Desc: Run gitlint
Output:
[BlueZ,5/5] iso-tester: add tests for multiple simultaneous CIG

WARNING: I3 - ignore-body-lines: gitlint will be switching from using Python regex 'match' (match beginning) to 'search' (match anywhere) semantics. Please review your ignore-body-lines.regex option accordingly. To remove this warning, set general.regex-style-search=True. More details: https://jorisroovers.github.io/gitlint/configuration/#regex-style-search
17: B2 Line has trailing whitespace: " "
##############################
Test: CheckSmatch - WARNING
Desc: Run smatch tool with source
Output:
emulator/btdev.c:416:29: warning: Variable length array is used.emulator/btdev.c:416:29: warning: Variable length array is used.
##############################
Test: ScanBuild - WARNING
Desc: Run Scan Build
Output:
emulator/btdev.c:1079:10: warning: Although the value stored to 'conn' is used in the enclosing expression, the value is never actually read from 'conn'
while ((conn = queue_find(dev->conns, match_handle,
^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
emulator/btdev.c:1391:13: warning: Access to field 'dev' results in a dereference of a null pointer (loaded from variable 'conn')
send_event(conn->dev, BT_HCI_EVT_AUTH_COMPLETE, &ev, sizeof(ev));
^~~~~~~~~
2 warnings generated.



---
Regards,
Linux Bluetooth

2023-05-22 20:20:50

by patchwork-bot+bluetooth

[permalink] [raw]
Subject: Re: [PATCH BlueZ 1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG

Hello:

This series was applied to bluetooth/bluez.git (master)
by Luiz Augusto von Dentz <[email protected]>:

On Sun, 21 May 2023 15:27:34 +0000 you wrote:
> There is a race between multiple connect() for CIS in the same CIG.
> connect() will both reconfigure the CIG and connect the CIS, but CIG
> cannot be reconfigured once one CIS has already connected. That these
> tests pass currently relies on some timing/event ordering in the
> emulator.
>
> Connecting multiple CIS in same CIG is meant to be done using
> DEFER_SETUP, so change the tests to use it, so we test the intended
> usage.
>
> [...]

Here is the summary with links:
- [BlueZ,1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG
https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=a88c74e29b6e
- [BlueZ,2/5] shared/tester: retain test failure status
https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=195b9abbae0e
- [BlueZ,3/5] btdev: support multiple CIG
https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=678265f37c28
- [BlueZ,4/5] btdev: report right reason for local Disconnect complete
https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=0c32cfdf9462
- [BlueZ,5/5] iso-tester: add tests for multiple simultaneous CIG
(no matching commit)

You are awesome, thank you!
--
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html



2023-05-22 20:31:33

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: [PATCH BlueZ 1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG

Hi Pauli,

On Mon, May 22, 2023 at 1:20 PM <[email protected]> wrote:
>
> Hello:
>
> This series was applied to bluetooth/bluez.git (master)
> by Luiz Augusto von Dentz <[email protected]>:
>
> On Sun, 21 May 2023 15:27:34 +0000 you wrote:
> > There is a race between multiple connect() for CIS in the same CIG.
> > connect() will both reconfigure the CIG and connect the CIS, but CIG
> > cannot be reconfigured once one CIS has already connected. That these
> > tests pass currently relies on some timing/event ordering in the
> > emulator.
> >
> > Connecting multiple CIS in same CIG is meant to be done using
> > DEFER_SETUP, so change the tests to use it, so we test the intended
> > usage.
> >
> > [...]
>
> Here is the summary with links:
> - [BlueZ,1/5] iso-tester: always use DEFER_SETUP for multiple CIS in same CIG
> https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=a88c74e29b6e
> - [BlueZ,2/5] shared/tester: retain test failure status
> https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=195b9abbae0e
> - [BlueZ,3/5] btdev: support multiple CIG
> https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=678265f37c28
> - [BlueZ,4/5] btdev: report right reason for local Disconnect complete
> https://git.kernel.org/pub/scm/bluetooth/bluez.git/?id=0c32cfdf9462
> - [BlueZ,5/5] iso-tester: add tests for multiple simultaneous CIG
> (no matching commit)

Ive ended up making some changes to patch 5/5 so it combines AC 1 with
AC 2, we can probably extend these tests to have more combinations of
different AC, etc, just to make sure the code can handle them
properly.


--
Luiz Augusto von Dentz