diff --git a/CHANGELOG.md b/CHANGELOG.md index a1020aa2a..f27fefd7b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,12 @@ All notable changes to this project will be documented in this file. The format is loosely based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/) and this project adheres to the [UHK Versioning](VERSIONING.md) conventions. +## [16.1.1] - 2026-01-16 + +- Fix: fix bluetooth issues caused by returning bad disconnect reasons - failing oob pairing, connected but otherwise unhandled connections. +- Fix: when the same dongle is switched to multiple times, it now remains greed instead of turning blue. +- Fix: exempt pairing scenarios from exponential advertising delay backoff. + ## [16.1.0] - 2026-01-16 Device Protocol: 4.17.0 | Module Protocol: 4.3.0 | Dongle Protocol: 1.0.2 | User Config: 13.0.0 | Hardware Config: 1.0.0 | Smart Macros: 3.**12.0** diff --git a/device/prj.conf.overlays/nrf_shared.conf b/device/prj.conf.overlays/nrf_shared.conf index 6442b02f3..1ffb6afb6 100644 --- a/device/prj.conf.overlays/nrf_shared.conf +++ b/device/prj.conf.overlays/nrf_shared.conf @@ -21,9 +21,14 @@ CONFIG_BT=y # CONFIG_BT_DEBUG_LOG=y CONFIG_BT_SMP=y -CONFIG_BT_L2CAP_TX_BUF_COUNT=5 CONFIG_BT_FILTER_ACCEPT_LIST=y +# increase these to make multiple connections more reliable +# this is a generic ai advice. +CONFIG_BT_ATT_TX_COUNT=10 +CONFIG_BT_CONN_TX_MAX=6 +CONFIG_BT_L2CAP_TX_BUF_COUNT=12 + # negotiate larger MTU for NUS CONFIG_BT_USER_DATA_LEN_UPDATE=y CONFIG_BT_BUF_ACL_RX_SIZE=251 diff --git a/device/src/bt_advertise.c b/device/src/bt_advertise.c index e4a4b2dfd..83d7b3b5e 100644 --- a/device/src/bt_advertise.c +++ b/device/src/bt_advertise.c @@ -81,7 +81,7 @@ ATTR_UNUSED static void setFilters(adv_config_t advConfig) { bt_le_filter_accept_list_clear(); if (advConfig.advType & (ADVERTISE_HID | ADVERTISE_NUS)) { - printk("Bt: filling adv allow filter\n"); + LOG_DBG("Bt: filling adv allow filter"); for (uint8_t connId = ConnectionId_HostConnectionFirst; connId <= ConnectionId_HostConnectionLast; connId++) { host_connection_t* hostConnection = HostConnection(connId); @@ -99,7 +99,7 @@ ATTR_UNUSED static void setFilters(adv_config_t advConfig) { } if (advConfig.advType & ADVERTISE_DIRECTED_NUS) { - printk("Bt: filling adv allow filter for \"directed\" advertising.\n"); + LOG_DBG("Bt: filling adv allow filter for \"directed\" advertising."); bt_le_filter_accept_list_add(advConfig.addr); } } @@ -136,14 +136,12 @@ uint8_t BtAdvertise_Start(adv_config_t advConfig) updateAdvertisingIcon(advConfig.advType & ADVERTISE_HID); - printk("Bt: start advertising\n"); - // Start advertising static struct bt_le_adv_param advParam; switch (advConfig.advType) { case ADVERTISE_HID: case ADVERTISE_NUS | ADVERTISE_HID: - LOG_INF("Adv: advertise nus+hid.\n"); + LOG_DBG("Adv: advertise nus+hid."); /* our devices don't check service uuids, so hid advertisement effectively advertises nus too */ advParam = *BT_LE_ADV_CONN_ONE_TIME; err = BT_LE_ADV_START(&advParam, adHid, sdHid); @@ -151,7 +149,7 @@ uint8_t BtAdvertise_Start(adv_config_t advConfig) break; case ADVERTISE_NUS: if (Cfg.Bt_DirectedAdvertisingAllowed) { - LOG_INF("Adv: advertise nus, with allow list.\n"); + LOG_DBG("Adv: advertise nus, with allow list."); setFilters(advConfig); advParam = *BT_LE_ADV_CONN_ONE_TIME; @@ -159,14 +157,14 @@ uint8_t BtAdvertise_Start(adv_config_t advConfig) err = BT_LE_ADV_START(&advParam, BY_SIDE(adNusLeft, adNusRight), sdNus); } else { - LOG_INF("Adv: advertise nus, without allow list.\n"); + LOG_DBG("Adv: advertise nus, without allow list."); advParam = *BT_LE_ADV_CONN_ONE_TIME; err = BT_LE_ADV_START(&advParam, BY_SIDE(adNusLeft, adNusRight), sdNus); } break; case ADVERTISE_DIRECTED_NUS: if (Cfg.Bt_DirectedAdvertisingAllowed) { - LOG_INF("Adv: direct advertise nus, with allow list.\n"); + LOG_DBG("Adv: direct advertise nus, with allow list."); setFilters(advConfig); advParam = *BT_LE_ADV_CONN_ONE_TIME; @@ -174,31 +172,31 @@ uint8_t BtAdvertise_Start(adv_config_t advConfig) err = BT_LE_ADV_START(&advParam, BY_SIDE(adNusLeft, adNusRight), sdNus); } else { - LOG_INF("Adv: direct advertise nus, without allow list.\n"); + LOG_DBG("Adv: direct advertise nus, without allow list."); advParam = *BT_LE_ADV_CONN_ONE_TIME; err = BT_LE_ADV_START(&advParam, BY_SIDE(adNusLeft, adNusRight), sdNus); } //// TODO: fix and reenable this? - // printk("Advertising against %s\n", GetAddrString(advConfig.addr)); + // printk("Advertising against %s", GetAddrString(advConfig.addr)); // advParam = *BT_LE_ADV_CONN_DIR_LOW_DUTY(advConfig.addr); // advParam.options |= BT_LE_ADV_OPT_DIR_ADDR_RPA; // err = BT_LE_ADV_START(&advParam, BY_SIDE(adNusLeft, adNusRight), sdNus); break; default: - LOG_INF("Adv: Attempted to start advertising without any type! Ignoring.\n"); + LOG_INF("Adv: Attempted to start advertising without any type! Ignoring."); return 0; } // Log it if (err == 0) { - LOG_INF("Adv: %s advertising successfully started\n", advTypeString); + LOG_INF("Adv: '%s' started", advTypeString); return 0; } else if (err == -EALREADY) { - LOG_INF("Adv: %s advertising continued\n", advTypeString); + LOG_INF("Adv: '%s' continued", advTypeString); return 0; } else { - LOG_INF("Adv: %s advertising failed to start (err %d), free connections: %d\n", advTypeString, err, BtConn_UnusedPeripheralConnectionCount()); + LOG_INF("Adv: '%s' failed to start (err %d), free connections: %d", advTypeString, err, BtConn_UnusedPeripheralConnectionCount()); return err; } } @@ -207,7 +205,7 @@ void BtAdvertise_Stop(void) { BT_TRACE_AND_ASSERT("ba2"); int err = bt_le_adv_stop(); if (err) { - LOG_WRN("Adv: Advertising failed to stop (err %d)\n", err); + LOG_WRN("Adv: Advertising failed to stop (err %d)", err); Bt_HandleError("BtAdvertise_Stop", err); } } @@ -262,7 +260,7 @@ adv_config_t BtAdvertise_Config() { } else { /** advertising needs a peripheral slot. When it is not free and we try to advertise, it will fail, and our code will try to * disconnect other devices in order to restore proper function. */ - LOG_INF("Adv: Current slot count is zero, not advertising!\n"); + LOG_INF("Adv: Current slot count is zero, not advertising!"); // BtConn_ListCurrentConnections(); return ADVERTISEMENT( 0 ); } @@ -270,7 +268,7 @@ adv_config_t BtAdvertise_Config() { case DeviceId_Uhk_Dongle: return ADVERTISEMENT( 0 ); default: - LOG_WRN("unknown device!\n"); + LOG_WRN("unknown device!"); return ADVERTISEMENT( 0 ); } } diff --git a/device/src/bt_conn.c b/device/src/bt_conn.c index 107fa8ceb..c56c7ab18 100644 --- a/device/src/bt_conn.c +++ b/device/src/bt_conn.c @@ -21,6 +21,7 @@ #include "nus_server.h" #include "device.h" #include "keyboard/oled/screens/pairing_screen.h" +#include "keyboard/oled/screens/screen_manager.h" #include "usb/usb.h" #include "keyboard/oled/widgets/widgets.h" #include @@ -37,7 +38,6 @@ #include "bt_health.h" #include "macros/status_buffer.h" - LOG_MODULE_REGISTER(Bt, LOG_LEVEL_INF); bool Bt_NewPairedDevice = false; @@ -47,17 +47,45 @@ struct bt_conn *auth_conn; #define BLE_KEY_LEN 16 #define BLE_ADDR_LEN 6 -// BT_HCI_ERR_REMOTE_LOW_RESOURCES - it is *their* resources that are low, so we probably shouldn't use this -// BT_HCI_ERR_LOCALHOST_TERM_CONN - this is our decision, bond should remain valid -// BT_HCI_ERR_REMOTE_USER_TERM_CONN - this is user's decision, bond should remain valid -// BT_HCI_ERR_AUTH_FAIL - permanent failure, bond should be removed - -#define BT_REASON_HID_GIVE_US_BREAK BT_HCI_ERR_LOCALHOST_TERM_CONN -#define BT_REASON_NOT_SELECTED BT_HCI_ERR_LOCALHOST_TERM_CONN +/* + * Reason codes are named from the perspective of the party that receives them. + * + * BT_HCI_ERR_REMOTE_LOW_RESOURCES + * - it is our resources that are low + * + * BT_HCI_ERR_LOCALHOST_TERM_CONN + * - this is their decision + * - we never send this. + * - don't trust llms on it. + * - if we actually use it, the connection will not actually disconnect + * + * BT_HCI_ERR_REMOTE_USER_TERM_CONN + * - this is probably the right thing to send + * - bond should remain valid + * + * BT_HCI_ERR_AUTH_FAIL + * - permanent failure + * - bond should be removed + * + * LLM says that according to the core spec, following disconnect reasons are valid: + * + * Code: 0x08 Zephyr Constant: BT_HCI_ERR_AUTH_FAIL Meaning: Authentication failure - signals permanent bond problem + * Code: 0x13 Zephyr Constant: BT_HCI_ERR_REMOTE_USER_TERM_CONN Meaning: Standard disconnect - "I'm disconnecting you" + * Code: 0x14 Zephyr Constant: BT_HCI_ERR_REMOTE_LOW_RESOURCES Meaning: Low resources - signals temporary resource issue + * Code: 0x15 Zephyr Constant: BT_HCI_ERR_REMOTE_POWER_OFF Meaning: Power off - device is shutting down + * Code: 0x1A Zephyr Constant: BT_HCI_ERR_UNSUPP_REMOTE_FEATURE Meaning: Unsupported feature + * Code: 0x29 Zephyr Constant: BT_HCI_ERR_PAIRING_NOT_SUPPORTED Meaning: Pairing not supported + * Code: 0x3B Zephyr Constant: BT_HCI_ERR_UNACCEPT_CONN_PARAM + * */ + +#define BT_REASON_HID_GIVE_US_BREAK BT_HCI_ERR_REMOTE_USER_TERM_CONN +#define BT_REASON_NOT_SELECTED BT_HCI_ERR_REMOTE_USER_TERM_CONN +#define BT_REASON_TEMPORARY BT_HCI_ERR_REMOTE_USER_TERM_CONN #define BT_REASON_PERMANENT BT_HCI_ERR_AUTH_FAIL -#define BT_REASON_UNSPECIFIED BT_HCI_ERR_UNSPECIFIED +#define BT_REASON_UNSPECIFIED BT_HCI_ERR_REMOTE_USER_TERM_CONN static void disconnectAllHids(); +static void auth_cancel(struct bt_conn *conn); peer_t Peers[PeerCount] = { { @@ -143,11 +171,19 @@ static struct bt_conn* unsetAuthConn(bool cancel_auth) { static void safeDisconnect(struct bt_conn *conn, int reason) { if (conn == auth_conn) { + LOG_INF("Unauthenticating %s", GetPeerStringByConn(conn)); unsetAuthConn(true); + + #if DEVICE_HAS_OLED + if (ActiveScreen == ScreenId_Pairing) { + PairingScreen_Cancel(); + } + #endif } else { struct bt_conn_info info; int err = bt_conn_get_info(conn, &info); if (err == 0 && info.state == BT_CONN_STATE_CONNECTED) { + LOG_INF("Disconnecting %s", GetPeerStringByConn(conn)); bt_conn_disconnect(conn, reason); } } @@ -237,7 +273,7 @@ static void enableDataLengthExtension(struct bt_conn *conn) { static void setLatency(struct bt_conn* conn, const struct bt_le_conn_param* params) { int err = bt_conn_le_param_update(conn, params); if (err) { - LOG_WRN("LE latencies update failed: %d\n", err); + LOG_WRN("LE latencies update failed: %d", err); Bt_HandleError("bt_conn_le_param_update", err); } } @@ -251,7 +287,7 @@ static void configureLatency(struct bt_conn *conn, latency_mode_t latencyMode) { const struct bt_le_conn_param conn_params = BT_LE_CONN_PARAM_INIT( 6, 6, // keep it low, lowest allowed is 6 (7.5ms), lowest supported widely is 9 (11.25ms) 0, // keeping it higher allows power saving on peripheral when there's nothing to send (keep it under 30 though) - 100 // connection timeout (*10ms) + 30 // connection timeout (*10ms) ); setLatency(conn, &conn_params); } @@ -263,7 +299,7 @@ static void configureLatency(struct bt_conn *conn, latency_mode_t latencyMode) { const struct bt_le_conn_param conn_params = BT_LE_CONN_PARAM_INIT( 6, 9, // keep it low, lowest allowed is 6 (7.5ms), lowest supported widely is 9 (11.25ms) 0, // keeping it higher allows power saving on peripheral when there's nothing to send (keep it under 30 though) - 100 // connection timeout (*10ms) + 30 // connection timeout (*10ms) ); setLatency(conn, &conn_params); } @@ -277,11 +313,11 @@ static void youAreNotWanted(struct bt_conn *conn) { uint32_t currentTime = k_uptime_get_32(); if (currentTime - lastAttemptTime < 1000 && BtAddrEq(bt_conn_get_dst(conn), &lastAddr)) { - LOG_WRN("Refusing connenction %s (this is not a selected connection)(this is repeated attempt!)\n", GetPeerStringByConn(conn)); + LOG_WRN("Refusing connenction %s (this is not a selected connection)(this is repeated attempt!)", GetPeerStringByConn(conn)); safeDisconnect(conn, BT_REASON_HID_GIVE_US_BREAK); } else { - LOG_WRN("Refusing connenction %s (this is not a selected connection (%d))\n", GetPeerStringByConn(conn), SelectedHostConnectionId); - safeDisconnect(conn, BT_REASON_NOT_SELECTED); + LOG_WRN("Refusing connenction %s (this is not a selected connection (%d))", GetPeerStringByConn(conn), SelectedHostConnectionId); + safeDisconnect(conn, BT_REASON_TEMPORARY); } LOG_INF(" Free peripheral slots: %d, Peripheral conn count: %d, bt pari mode: %d", BtConn_UnusedPeripheralConnectionCount(), @@ -294,7 +330,7 @@ static void youAreNotWanted(struct bt_conn *conn) { } ATTR_UNUSED static void youAreNotAuthenticated(struct bt_conn *conn) { - LOG_WRN("Implement this!\n"); + LOG_WRN("Implement this!"); } void BtConn_UpdateHostConnectionPeerAllocations() { @@ -307,7 +343,7 @@ void BtConn_UpdateHostConnectionPeerAllocations() { if (newId != ConnectionId_Invalid && newId != currentId) { Connections_MoveConnection(peerId, currentId, newId); } else if (newId == ConnectionId_Invalid) { - LOG_WRN("No host connection found for peer %s, disconnecting\n", Peers[peerId].name); + LOG_WRN("No host connection found for peer %s, disconnecting", Peers[peerId].name); safeDisconnect(conn, BT_REASON_UNSPECIFIED); } } @@ -348,7 +384,7 @@ static uint8_t assignPeer(struct bt_conn* conn, uint8_t connectionId, uint8_t co uint8_t peerId = allocateHostPeer(connectionType); if (peerId == PeerIdUnknown) { - LOG_WRN("No peer slot available for connection %d\n", connectionId); + LOG_WRN("No peer slot available for connection %d", connectionId); safeDisconnect(conn, BT_REASON_UNSPECIFIED); return PeerIdUnknown; } @@ -366,25 +402,25 @@ void bt_foreach_list_current_connections(struct bt_conn *conn, void *data) { int8_t peerId = GetPeerIdByConn(conn); if (peerId == PeerIdUnknown) { - LogU(" - %s\n", GetPeerStringByConn(conn)); + LogU(" - %s", GetPeerStringByConn(conn)); } else { - LogU(" - peer %d(%s), connection %d\n", peerId, GetPeerStringByConn(conn), Peers[peerId].connectionId); + LogU(" - peer %d(%s), connection %d", peerId, GetPeerStringByConn(conn), Peers[peerId].connectionId); } } void BtConn_ListCurrentConnections() { - LogU("Current connections:\n"); + LogU("Current connections:"); bt_conn_foreach(BT_CONN_TYPE_LE, bt_foreach_list_current_connections, NULL); } static void bt_foreach_print_bond(const struct bt_bond_info *info, void *user_data) { - LogU(" - %s\n", GetAddrString(&info->addr)); + LogU(" - %s", GetAddrString(&info->addr)); } void BtConn_ListAllBonds() { - LogU("All bonds:\n"); + LogU("All bonds:"); bt_foreach_bond(BT_ID_DEFAULT, bt_foreach_print_bond, NULL); } @@ -397,6 +433,8 @@ static bool isWantedInHidPairingMode(struct bt_conn *conn, bool alreadyAuthentic if (!result) { LOG_INF(" Not wanted in HID pairing mode: isLeft: %d, isBonded: %d, alreadyAuth: %d", isLeftConnection, isBonded, alreadyAuthenticated); + } else { + LOG_INF(" Is wanted in HID pairing mode: isLeft: %d, isBonded: %d, alreadyAuth: %d", isLeftConnection, isBonded, alreadyAuthenticated); } return result; @@ -437,7 +475,7 @@ static bool isWantedInNormalMode(struct bt_conn *conn, connection_id_t connectio */ // We can get here during pairing where the connection collides with itself. - LOG_INF(" Not wanted: this is HID collision\n"); + LOG_INF(" Not wanted: this is HID collision"); return false; } else if (selectedConnectionIsBleHid) { if (!isSelectedConnection) { @@ -467,7 +505,7 @@ static bool isWanted(struct bt_conn *conn, bool alreadyAuthenticated, connection static void connectNus(struct bt_conn *conn, connection_id_t connectionId, connection_type_t connectionType) { uint8_t peerId = assignPeer(conn, connectionId, connectionType); - LOG_INF("connected to %s\n", GetPeerStringByConn(conn)); + LOG_DBG("connected to %s", GetPeerStringByConn(conn)); configureLatency(conn, LatencyMode_NUS); enableDataLengthExtension(conn); @@ -475,7 +513,7 @@ static void connectNus(struct bt_conn *conn, connection_id_t connectionId, conne bool isRightClient = DEVICE_IS_UHK80_RIGHT && peerId == PeerIdLeft; bool isDongleClient = DEVICE_IS_UHK_DONGLE && peerId == PeerIdRight; if ( isRightClient || isDongleClient ) { - LOG_INF("Initiating NUS connection with %s\n", GetPeerStringByConn(conn)); + LOG_INF("Initiating NUS connection with %s", GetPeerStringByConn(conn)); NusClient_Connect(conn); } } @@ -486,9 +524,9 @@ static void connectHid(struct bt_conn *conn, connection_id_t connectionId, conne configureLatency(conn, LatencyMode_NUS); // Assume that HOGP is ready - LOG_INF("Established HID connection with %s\n", GetPeerStringByConn(conn)); + LOG_INF("Established HID connection with %s", GetPeerStringByConn(conn)); Connections_SetState(connectionId, ConnectionState_Ready); - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in connectHid"); + BtManager_StartScanningAndAdvertisingAsync(false, "connectHid"); } #define BT_UUID_NUS_VAL BT_UUID_128_ENCODE(0x6e400001, 0xb5a3, 0xf393, 0xe0a9, 0xe50e24dcca9e) @@ -497,7 +535,7 @@ static void connectHid(struct bt_conn *conn, connection_id_t connectionId, conne ATTR_UNUSED static uint8_t discover_func(struct bt_conn *conn, const struct bt_gatt_attr *attr, struct bt_gatt_discover_params *params) { if (!attr) { - LOG_INF("Service discovery completed, connection wasn't matched.\n"); + LOG_DBG("Service discovery completed, connection wasn't matched."); // TODO: consider setting a timer to disconnect the connection if neither auth nor security is Established return BT_GATT_ITER_STOP; } @@ -514,7 +552,7 @@ ATTR_UNUSED static uint8_t discover_func(struct bt_conn *conn, const struct bt_g } if (!isPairedConnection && DEVICE_IS_UHK80_RIGHT) { - LOG_INF("Unknown NUS trying to connect. Refusing!\n"); + LOG_INF("Unknown NUS trying to connect. Refusing!"); safeDisconnect(conn, BT_REASON_PERMANENT); } return BT_GATT_ITER_STOP; @@ -532,7 +570,7 @@ static void connectUnknown(struct bt_conn *conn) { #if DEVICE_IS_UHK80_RIGHT || DEVICE_IS_UHK_DONGLE int err; - LOG_INF("Bt connected to unknown. Starting discovery.\n"); + LOG_DBG("Bt connected to unknown. Starting discovery."); static struct bt_gatt_discover_params discover_params; discover_params.uuid = NULL; // Will discover all services discover_params.start_handle = 0x0001; @@ -542,7 +580,7 @@ static void connectUnknown(struct bt_conn *conn) { err = bt_gatt_discover(conn, &discover_params); if (err) { - LOG_WRN("Service discovery failed (err %u)\n", err); + LOG_WRN("Service discovery failed (err %u)", err); Bt_HandleError("bt_gatt_discover", err); return; } @@ -552,14 +590,14 @@ static void connectUnknown(struct bt_conn *conn) { static void connected(struct bt_conn *conn, uint8_t err) { BT_TRACE_AND_ASSERT("bc1"); - LOG_INF("Connected cb\n"); + LOG_DBG("Connected cb"); // Without this, linux pairing fails, because tiny 27 byte packets // exhaust acl buffers easily enableDataLengthExtension(conn); if (err) { - LOG_WRN("Failed to connect to %s, err %u\n", GetPeerStringByConn(conn), err); + LOG_WRN("Failed to connect to %s, err %u", GetPeerStringByConn(conn), err); BtManager_StartScanningAndAdvertising(); return; } @@ -568,11 +606,11 @@ static void connected(struct bt_conn *conn, uint8_t err) { connection_id_t connectionId = Connections_GetConnectionIdByHostAddr(addr); connection_type_t connectionType = Connections_Type(connectionId); - LOG_INF("connected %s, %d %d\n", GetPeerStringByConn(conn), connectionId, connectionType); + LOG_INF("Connected %s, %d %d", GetPeerStringByConn(conn), connectionId, connectionType); if (connectionId == ConnectionId_Invalid) { connectUnknown(conn); - BtManager_StartScanningAndAdvertisingAsync(true, "StartScanningAndAdvertisingAsync in connected - invalid connection"); + BtManager_StartScanningAndAdvertisingAsync(true, "connected - invalid connection"); } else { if (isWanted(conn, false, connectionId, connectionType)) { @@ -580,7 +618,7 @@ static void connected(struct bt_conn *conn, uint8_t err) { // advertising/scanning needs to be started only after peers are assigned :-/ } else { youAreNotWanted(conn); - BtManager_StartScanningAndAdvertisingAsync(true, "StartScanningAndAdvertisingAsync in connected - they are not wanted"); + BtManager_StartScanningAndAdvertisingAsync(true, "connected - they are not wanted"); } } @@ -596,7 +634,7 @@ static void disconnected(struct bt_conn *conn, uint8_t reason) { ARG_UNUSED(peerId); - LOG_INF("Bt disconnected from %s, reason %u\n", GetPeerStringByConn(conn), reason); + LOG_INF("Disconnected from %s, reason %u", GetPeerStringByConn(conn), reason); if (DEVICE_IS_UHK80_LEFT && peerId == PeerIdRight) { NusServer_Disconnected(); @@ -624,7 +662,7 @@ static void disconnected(struct bt_conn *conn, uint8_t reason) { } if (!BtManager_Restarting) { - BtManager_StartScanningAndAdvertisingAsync(true, "StartScanningAndAdvertisingAsync in disconnected"); + BtManager_StartScanningAndAdvertisingAsync(true, "disconnected"); } if (conn == auth_conn) { @@ -637,7 +675,7 @@ void Bt_SetConnectionConfigured(struct bt_conn* conn) { uint8_t peerId = GetPeerIdByConn(conn); if (Connections[Peers[peerId].connectionId].state != ConnectionState_Ready) { Connections_SetState(Peers[peerId].connectionId, ConnectionState_Ready); - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in SetConnectionConfigured"); + BtManager_StartScanningAndAdvertisingAsync(false, "SetConnectionConfigured"); } } @@ -655,7 +693,7 @@ static bool isUhkDeviceConnection(connection_type_t connectionType) { static void connectAuthenticatedConnection(struct bt_conn *conn, connection_id_t connectionId, connection_type_t connectionType) { // in case we don't have free connection slots and this is not the selected connection, then refuse if (!isWanted(conn, true, connectionId, connectionType)) { - LOG_WRN("Refusing authenticated connenction %d (this is not a selected connection(%d))\n", connectionId, SelectedHostConnectionId); + LOG_WRN("Refusing authenticated connenction %d (this is not a selected connection(%d))", connectionId, SelectedHostConnectionId); youAreNotWanted(conn); return; } @@ -673,7 +711,7 @@ static void connectAuthenticatedConnection(struct bt_conn *conn, connection_id_t default: LOG_ERR("Authenticated connection is not known. Disconnecting %s", GetPeerStringByConn(conn)); safeDisconnect(conn, BT_HCI_ERR_AUTH_FAIL); - BtManager_StartScanningAndAdvertisingAsync(true, "StartScanningAndAdvertisingAsync in authenticatedConnection - is unknown"); + BtManager_StartScanningAndAdvertisingAsync(true, "authenticatedConnection - is unknown"); break; } } @@ -682,7 +720,7 @@ static void securityChanged(struct bt_conn *conn, bt_security_t level, enum bt_s BT_TRACE_AND_ASSERT("bc3"); // In case of failure, disconnect if (err || (level < BT_SECURITY_L4 && !Cfg.Bt_AllowUnsecuredConnections)) { - LOG_WRN("Bt security failed: %s, level %u, err %d, disconnecting\n", GetPeerStringByConn(conn), level, err); + LOG_WRN("Bt security failed: %s, level %u, err %d, disconnecting", GetPeerStringByConn(conn), level, err); struct bt_conn_info info; int err = bt_conn_get_info(conn, &info); @@ -700,7 +738,7 @@ static void securityChanged(struct bt_conn *conn, bt_security_t level, enum bt_s // Ignore connection that is being paired. At this point, the central is // probably talking to us via an anonymous address, and it will yet change. if (conn == auth_conn) { - LOG_INF("Bt connection secured: %s, level %u. It is auth_conn, so ignoring.\n", GetPeerStringByConn(conn), level); + LOG_DBG("Bt connection secured: %s, level %u. It is auth_conn, so ignoring.", GetPeerStringByConn(conn), level); return; } @@ -712,7 +750,7 @@ static void securityChanged(struct bt_conn *conn, bt_security_t level, enum bt_s __attribute__((unused)) static void infoLatencyParamsUpdated(struct bt_conn* conn, uint16_t interval, uint16_t latency, uint16_t timeout) { - LOG_INF("%s conn params: interval=%u ms, latency=%u, timeout=%u ms\n", GetPeerStringByConn(conn), interval * 5 / 4, latency, timeout * 10); + LOG_DBG("%s conn params: interval=%u ms, latency=%u, timeout=%u ms", GetPeerStringByConn(conn), interval * 5 / 4, latency, timeout * 10); bool isUhkPeer = isUhkDeviceConnection(Connections_Type(Peers[GetPeerIdByConn(conn)].connectionId)); @@ -739,12 +777,12 @@ static void auth_passkey_entry(struct bt_conn *conn) { Trace_Printc("br1"); setAuthConn(conn); - LOG_INF("Received passkey pairing inquiry.\n"); + LOG_INF("Received passkey pairing inquiry."); enableDataLengthExtension(conn); if (!auth_conn) { - LOG_INF("Returning: no auth conn\n"); + LOG_INF("Returning: no auth conn"); return; } @@ -756,7 +794,7 @@ static void auth_passkey_entry(struct bt_conn *conn) { connection_type_t connectionType = Connections_Type(Peers[peerId].connectionId); bool isUhkPeer = isUhkDeviceConnection(connectionType); if (isUhkPeer || isUhkPeerByAddr || BtPair_PairingMode == PairingMode_Oob) { - LOG_INF("refusing passkey authentification for %s\n", GetPeerStringByConn(conn)); + LOG_INF("refusing passkey authentification for %s", GetPeerStringByConn(conn)); bt_conn_auth_cancel(conn); return; } @@ -765,11 +803,11 @@ static void auth_passkey_entry(struct bt_conn *conn) { PairingScreen_AskForPassword(); #endif - LOG_INF("Type `uhk passkey xxxxxx` to pair, or `uhk passkey -1` to reject\n"); + LOG_INF("Type `uhk passkey xxxxxx` to pair, or `uhk passkey -1` to reject"); } static void auth_cancel(struct bt_conn *conn) { - LOG_INF("Pairing cancelled: peer %s\n", GetPeerStringByConn(conn)); + LOG_INF("Pairing cancelled: peer %s", GetPeerStringByConn(conn)); if (auth_conn) { Trace_Printc("bu5"); @@ -793,12 +831,12 @@ static void auth_oob_data_request(struct bt_conn *conn, struct bt_conn_oob_info struct bt_le_oob* oobRemote = BtPair_GetRemoteOob(); if (memcmp(info.le.remote->a.val, oobRemote->addr.a.val, sizeof(info.le.remote->a.val))) { - LOG_WRN("Addresses not matching! Cancelling authentication\n"); + LOG_WRN("Addresses not matching! Cancelling authentication"); bt_conn_auth_cancel(conn); return; } - LOG_INF("Pairing OOB data requested!\n"); + LOG_INF("Pairing OOB data requested!"); bt_le_oob_set_sc_data(conn, &oobLocal->le_sc_data, &oobRemote->le_sc_data); } @@ -812,7 +850,7 @@ static struct bt_conn_auth_cb conn_auth_callbacks = { // Auth info callbacks static void pairing_complete(struct bt_conn *conn, bool bonded) { - LOG_WRN("Pairing completed: %s, bonded %d\n", GetPeerStringByConn(conn), bonded); + LOG_WRN("Pairing completed: %s, bonded %d", GetPeerStringByConn(conn), bonded); bt_addr_le_t addr = *bt_conn_get_dst(conn); @@ -820,7 +858,7 @@ static void pairing_complete(struct bt_conn *conn, bool bonded) { BtPair_EndPairing(true, "Successfuly bonded!"); // Disconnect it so that the connection is established only after it is identified as a host connection - bt_conn_disconnect(conn, BT_HCI_ERR_REMOTE_USER_TERM_CONN); + bt_conn_disconnect(conn, BT_REASON_TEMPORARY); } else { BtPair_EndPairing(true, "Successfuly bonded!"); @@ -833,7 +871,7 @@ static void pairing_complete(struct bt_conn *conn, bool bonded) { Bt_NewPairedDevice = true; if (connectionId == ConnectionId_Invalid) { - LOG_WRN("No connection slot available for newly paired device %s\n", GetPeerStringByConn(conn)); + LOG_WRN("No connection slot available for newly paired device %s", GetPeerStringByConn(conn)); NotifyPrintf("No slot available!"); safeDisconnect(conn, BT_REASON_UNSPECIFIED); return; @@ -842,7 +880,7 @@ static void pairing_complete(struct bt_conn *conn, bool bonded) { HostConnection_SetSelectedConnection(connectionId); - LOG_INF("Pairing complete, passing connection %d to authenticatedConnection handler. Selected conn is %d\n", connectionId, SelectedHostConnectionId); + LOG_INF("Pairing complete, passing connection %d to authenticatedConnection handler. Selected conn is %d", connectionId, SelectedHostConnectionId); // we have to connect from here, because central changes its address *after* setting security connectAuthenticatedConnection(conn, connectionId, connectionType); @@ -854,7 +892,7 @@ static void pairing_complete(struct bt_conn *conn, bool bonded) { PairingScreen_Feedback(true); } - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in pairing_complete"); + BtManager_StartScanningAndAdvertisingAsync(false, "pairing_complete"); } static void bt_foreach_conn_cb(struct bt_conn *conn, void *user_data) { @@ -882,7 +920,7 @@ void BtConn_DisconnectOne(connection_id_t connectionId) { static void bt_foreach_conn_cb_disconnect_unidentified(struct bt_conn *conn, void *user_data) { peer_t* peer = getPeerByConn(conn); if (!peer) { - LOG_INF(" disconnecting unassigned connection %s\n", GetPeerStringByConn(conn)); + LOG_INF(" disconnecting unassigned connection %s", GetPeerStringByConn(conn)); safeDisconnect(conn, BT_REASON_NOT_SELECTED); } } @@ -900,12 +938,15 @@ static void pairing_failed(struct bt_conn *conn, enum bt_security_err reason) { if (auth_conn == conn) { Trace_Printc("bu7"); - LOG_WRN("Pairing of auth conn failed because of %d\n", reason); - unsetAuthConn(false); + LOG_WRN("Pairing of auth conn failed because of %d", reason); + unsetAuthConn(true); PairingScreen_Feedback(false); } - LOG_WRN("Pairing failed: %s, reason %d\n", GetPeerStringByConn(conn), reason); + // TODO: should we here? + //safeDisconnect(conn, BT_REASON_PERMANENT); + + LOG_WRN("Pairing failed: %s, reason %d", GetPeerStringByConn(conn), reason); } @@ -928,12 +969,12 @@ void BtConn_Init(void) { err = bt_conn_auth_cb_register(&conn_auth_callbacks); if (err) { - LOG_WRN("Failed to register authorization callbacks.\n"); + LOG_WRN("Failed to register authorization callbacks."); } err = bt_conn_auth_info_cb_register(&conn_auth_info_callbacks); if (err) { - LOG_WRN("Failed to register authorization info callbacks.\n"); + LOG_WRN("Failed to register authorization info callbacks."); } } @@ -952,7 +993,7 @@ void num_comp_reply(int passkey) { if (passkey >= 0) { bt_conn_auth_passkey_entry(conn, passkey); - LOG_INF("Sending passkey to conn %s\n", GetPeerStringByConn(conn)); + LOG_INF("Sending passkey to conn %s", GetPeerStringByConn(conn)); } else { conn = unsetAuthConn(true); } @@ -984,7 +1025,7 @@ ATTR_UNUSED static void disconnectOldestHost() { } if (oldestPeerId != PeerIdUnknown) { - LOG_INF("Disconnecting oldest host %d\n", oldestPeerId); + LOG_INF("Disconnecting oldest host %d", oldestPeerId); safeDisconnect(Peers[oldestPeerId].conn, BT_REASON_NOT_SELECTED); } } @@ -1020,7 +1061,7 @@ void BtConn_ReserveConnections() { disconnectOldestHost(); // Advertising will get started when the host actually gets disconnected } else { - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in ReserveConnections"); + BtManager_StartScanningAndAdvertisingAsync(false, "ReserveConnections"); } WIDGET_REFRESH(&TargetWidget); } else { @@ -1028,7 +1069,7 @@ void BtConn_ReserveConnections() { // Is this even a legal code path? // Just log for now. if (hostState == ConnectionState_Connected) { - LOG_WRN("Selected host is connected but not yet ready in ReserveConnections. Waiting...\n"); + LOG_WRN("Selected host is connected but not yet ready in ReserveConnections. Waiting..."); } } #endif @@ -1045,10 +1086,10 @@ void Bt_SetEnabled(bool enabled) { Cfg.Bt_Enabled = enabled; if (enabled) { - LOG_WRN("Starting bluetooth on request.\n"); + LOG_WRN("Starting bluetooth on request."); BtManager_StartScanningAndAdvertising(); } else { - LOG_WRN("Shutting down bluetooth on request!\n"); + LOG_WRN("Shutting down bluetooth on request!"); BtManager_StopBt(); BtConn_DisconnectAll(); } diff --git a/device/src/bt_manager.c b/device/src/bt_manager.c index 6231997bc..cff0ceb04 100644 --- a/device/src/bt_manager.c +++ b/device/src/bt_manager.c @@ -30,10 +30,10 @@ bool BtManager_Restarting = false; static void bt_ready(int err) { if (err) { - LOG_WRN("Bluetooth init failed (err %d)\n", err); + LOG_WRN("Bluetooth init failed (err %d)", err); Bt_HandleError("bt_ready", err); } else { - LOG_INF("Bluetooth initialized successfully\n"); + LOG_INF("Bluetooth initialized successfully"); } } @@ -44,7 +44,7 @@ void BtManager_InitBt() { if (DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT) { int err = NusServer_Init(); if (err) { - LOG_WRN("NusServer_Init failed with error %d\n", err); + LOG_WRN("NusServer_Init failed with error %d", err); Bt_HandleError("NusServer_Init", err); } } @@ -57,7 +57,7 @@ void BtManager_InitBt() { void BtManager_StartBt() { BT_TRACE_AND_ASSERT("bm2"); - LOG_INF("Starting bluetooth services.\n"); + LOG_INF("Starting bluetooth services."); if (!Cfg.Bt_Enabled) { return; @@ -72,19 +72,39 @@ void BtManager_StartBt() { void BtManager_StopBt() { BT_TRACE_AND_ASSERT("bm3"); - if (DEVICE_IS_UHK80_RIGHT) { - HOGP_Disable(); - } + + k_sleep(K_MSEC(10)); + + LOG_INF("OOB: Stopping bluetooth services."); + + EventScheduler_Unschedule(EventSchedulerEvent_BtStartScanningAndAdvertising); if (DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT) { BtAdvertise_Stop(); } + k_sleep(K_MSEC(10)); + if (DEVICE_IS_UHK80_RIGHT || DEVICE_IS_UHK_DONGLE) { BtScan_Stop(); } + EventScheduler_Unschedule(EventSchedulerEvent_BtStartScanningAndAdvertising); + + k_sleep(K_MSEC(10)); + + BtConn_DisconnectAll(); + + k_sleep(K_MSEC(10)); + + + if (DEVICE_IS_UHK80_RIGHT) { + HOGP_Disable(); + } + BtAdvertise_DisableAdvertisingIcon(); + + LOG_INF("OOB: Bluetooth stopped"); } @@ -92,16 +112,30 @@ void BtManager_StartScanningAndAdvertisingAsync(bool wasAggresive, const char* e BT_TRACE_AND_ASSERT("bm4"); uint32_t maxDelay = 5000; uint32_t minDelay = 100; + uint32_t expDelay; static int8_t aggressiveTries = 0; - aggressiveTries = wasAggresive ? aggressiveTries + 1 : 0; - aggressiveTries = MAX(0, aggressiveTries); - aggressiveTries = MIN(aggressiveTries, 16); + if (BtPair_PairingMode == PairingMode_Oob) { + return; + } - uint32_t expDelay = MIN(maxDelay, minDelay << aggressiveTries); + bool weArePairing = BtPair_PairingMode == PairingMode_PairHid; + bool weAreSwitching = SelectedHostConnectionId != ConnectionId_Invalid; + if (weArePairing || weAreSwitching) { + expDelay = minDelay; + } else { + if (wasAggresive) { + aggressiveTries = aggressiveTries + 1; + } else { + aggressiveTries = 0; + } + aggressiveTries = MAX(0, aggressiveTries); + aggressiveTries = MIN(aggressiveTries, 64); + expDelay = MIN(maxDelay, minDelay << (aggressiveTries/2)); + } - LOG_INF("btManager: BtManager_StartScanningAndAdvertisingAsync because %s, delay %d\n", eventLabel, expDelay); + LOG_INF("BtManager: Scheduling scan/adv in %dms. (%s)", expDelay, eventLabel); EventScheduler_Reschedule(Timer_GetCurrentTime() + expDelay, EventSchedulerEvent_BtStartScanningAndAdvertising, eventLabel); } @@ -143,8 +177,6 @@ void BtManager_StartScanningAndAdvertising() { bool dongleShouldScanForOob = DEVICE_IS_UHK_DONGLE && BtPair_PairingMode == PairingMode_Oob && BtPair_PairingAsCentral; bool shouldScan = rightShouldScanForPeer || rightShouldScanForOob || dongleShouldScanForPeer || dongleShouldScanForOob; - LOG_INF("btManager: should scanAndAdvertise %d %d\n", shouldScan, shouldAdvertise); - if (shouldAdvertise || shouldScan) { const char* label = ""; if (shouldAdvertise && shouldScan) { @@ -154,7 +186,7 @@ void BtManager_StartScanningAndAdvertising() { } else if (shouldScan) { label = "scanning"; } - LOG_INF("Starting %s, try %d!\n", label, try); + LOG_INF("BtManager: Start '%s' (%d).", label, try); } #ifdef CONFIG_BT_PERIPHERAL @@ -188,7 +220,7 @@ void BtManager_StartScanningAndAdvertising() { void BtManager_RestartBt() { BT_TRACE_AND_ASSERT("bm6"); - LOG_INF("Going to reset bluetooth stack\n"); + LOG_INF("Going to reset bluetooth stack"); BtManager_Restarting = true; int err; @@ -199,7 +231,7 @@ void BtManager_RestartBt() { err = bt_disable(); if (err) { - LOG_WRN("Bluetooth disable failed (err %d)\n", err); + LOG_WRN("Bluetooth disable failed (err %d)", err); Bt_HandleError("bt_disable", err); return; } @@ -209,13 +241,13 @@ void BtManager_RestartBt() { err = bt_hci_cmd_send(BT_HCI_OP_RESET, NULL); if (err) { - LOG_WRN("HCI Reset failed (err %d)\n", err); + LOG_WRN("HCI Reset failed (err %d)", err); Bt_HandleError("bt_hci_cmd_send", err); } err = bt_enable(bt_ready); if (err) { - LOG_WRN("Bluetooth init failed (err %d)\n", err); + LOG_WRN("Bluetooth init failed (err %d)", err); Bt_HandleError("bt_enable", err); } @@ -225,7 +257,7 @@ void BtManager_RestartBt() { BtManager_Restarting = false; - LOG_INF("Bluetooth subsystem restart finished\n"); + LOG_INF("Bluetooth subsystem restart finished"); } void BtManager_RestartBtAsync() { diff --git a/device/src/bt_pair.c b/device/src/bt_pair.c index 003edfd0d..44dd33373 100644 --- a/device/src/bt_pair.c +++ b/device/src/bt_pair.c @@ -36,10 +36,9 @@ static pairing_mode_t defaultPairingMode() { } static void enterOobPairingMode() { - printk("--- Entering pairing mode. Going to stop BT and disconnect all connections. ---\n"); + printk("------ Entering oob pairing mode. Going to stop BT and disconnect all connections. ------\n"); BtPair_PairingMode = PairingMode_Oob; BtManager_StopBt(); - BtConn_DisconnectAll(); } struct bt_le_oob* BtPair_GetLocalOob() { @@ -87,7 +86,7 @@ void BtManager_EnterMode(pairing_mode_t mode, bool toggle) { if (mode == PairingMode_PairHid) { BtConn_MakeSpaceForHid(); } - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in BtManager_EnterMode - start advertising"); + BtManager_StartScanningAndAdvertisingAsync(false, "BtManager_EnterMode - start advertising"); if (mode != defaultMode) { EventScheduler_Reschedule(k_uptime_get_32() + USER_PAIRING_TIMEOUT, EventSchedulerEvent_EndBtPairing, "User pairing mode timeout."); } @@ -112,8 +111,9 @@ void BtPair_PairCentral() { BtPair_PairingAsCentral = true; Settings_Reload(); bt_le_oob_set_sc_flag(true); + printk ("OOB: Scanning preparing...\n"); BtScan_Start(); - printk ("Scanning for pairable device\n"); + printk ("OOB: Scanning for pairable device\n"); EventScheduler_Reschedule(k_uptime_get_32() + PAIRING_TIMEOUT, EventSchedulerEvent_EndBtPairing, "Oob pairing timeout."); } #endif @@ -124,8 +124,9 @@ void BtPair_PairPeripheral() { BtPair_PairingAsCentral = false; Settings_Reload(); bt_le_oob_set_sc_flag(true); + printk ("OOB: Advertisement preparing...\n"); BtAdvertise_Start(BtAdvertise_Config()); - printk ("Waiting for central to pair to me.\n"); + printk ("OOB: Waiting for central to pair to me.\n"); EventScheduler_Reschedule(k_uptime_get_32() + PAIRING_TIMEOUT, EventSchedulerEvent_EndBtPairing, "Oob pairing timeout."); } #endif @@ -156,7 +157,7 @@ void BtPair_EndPairing(bool success, const char* msg) { BtAdvertise_Stop(); #endif - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in BtPair_EndPairing"); + BtManager_StartScanningAndAdvertisingAsync(false, "BtPair_EndPairing"); } struct delete_args_t { @@ -242,6 +243,8 @@ void BtPair_Unpair(const bt_addr_le_t addr) { // Update settings Settings_Reload(); UsbCommand_UpdateNewPairingsFlag(); + + BT_TRACE_AND_ASSERT("bpr6"); } static void bt_foreach_bond_cb_delete_non_lr(const struct bt_bond_info *info, void *user_data) { diff --git a/device/src/connections.c b/device/src/connections.c index dd10e98b8..a6cdc8f57 100644 --- a/device/src/connections.c +++ b/device/src/connections.c @@ -16,6 +16,9 @@ #include "config_manager.h" #include "bt_pair.h" #include "usb_commands/usb_command_get_new_pairings.h" +#include + +LOG_MODULE_REGISTER(Conn, LOG_LEVEL_INF); connection_t Connections[ConnectionId_Count] = { [ConnectionId_UsbHidRight] = { .isAlias = true }, @@ -88,7 +91,7 @@ const char* Connections_GetStaticName(connection_id_t connectionId) { return getStaticName(connectionId); } -static void reportConnectionState(connection_id_t connectionId, const char* message) { +static void reportConnectionState(connection_id_t connectionId) { connectionId = resolveAliases(connectionId); bool isHostConnection = false; @@ -117,9 +120,9 @@ static void reportConnectionState(connection_id_t connectionId, const char* mess if (isHostConnection) { host_connection_t* hc = HostConnection(connectionId); - LogU("%s: %s%d(%.*s, %s)%s%s%s%s\n", message, name, connectionId - ConnectionId_HostConnectionFirst, hc->name.end - hc->name.start, hc->name.start, getStateString(Connections[connectionId].state), peerLabel, peerString, activeLabel, selectedLabel); + LOG_INF("%s: %d(%.*s, %s)%s%s%s%s", name, connectionId - ConnectionId_HostConnectionFirst, hc->name.end - hc->name.start, hc->name.start, getStateString(Connections[connectionId].state), peerLabel, peerString, activeLabel, selectedLabel); } else { - LogU("%s: %s(%s)%s%s%s%s\n", message, name, getStateString(Connections[connectionId].state), peerLabel, peerString, activeLabel, selectedLabel); + LOG_INF("%s: (%s)%s%s%s%s", name, getStateString(Connections[connectionId].state), peerLabel, peerString, activeLabel, selectedLabel); } } @@ -131,7 +134,7 @@ void Connections_ResetWatermarks(connection_id_t connectionId) { } void Connections_ReportState(connection_id_t connectionId) { - reportConnectionState(connectionId, "Conn state"); + reportConnectionState(connectionId); } connection_state_t Connections_GetState(connection_id_t connectionId) { @@ -144,7 +147,7 @@ void Connections_SetState(connection_id_t connectionId, connection_state_t state if ( Connections[connectionId].state != state ) { Connections[connectionId].state = state; - reportConnectionState(connectionId, "Conn state"); + reportConnectionState(connectionId); Connections_ResetWatermarks(connectionId); @@ -195,7 +198,7 @@ connection_type_t Connections_Type(connection_id_t connectionId) { return ConnectionType_Unknown; break; } - printk("Unhandled connectionId %d\n", connectionId); + LOG_ERR("Unhandled connectionId %d", connectionId); return ConnectionType_Unknown; } @@ -233,7 +236,7 @@ connection_target_t Connections_Target(connection_id_t connectionId) { case ConnectionId_Invalid: return ConnectionTarget_None; } - printk("Unhandled connectionId %d\n", connectionId); + LOG_ERR("Unhandled connectionId %d", connectionId); return ConnectionTarget_None; } @@ -382,8 +385,8 @@ bool Connections_IsActiveHostConnection(connection_id_t connectionId) { return resolveAliases(connectionId) == ActiveHostConnectionId; } -static void setCurrentDongleToStandby() { - if (Connections_IsHostConnection(ActiveHostConnectionId) && HostConnection(ActiveHostConnectionId)->type == HostConnectionType_Dongle) { +static void setDongleToStandby(connection_id_t connectionId) { + if (Connections_IsHostConnection(connectionId) && HostConnection(connectionId)->type == HostConnectionType_Dongle) { bool standby = true; Messenger_Send2(DeviceId_Uhk_Dongle, MessageId_StateSync, StateSyncPropertyId_DongleStandby, (const uint8_t*)&standby, 1); } @@ -428,9 +431,11 @@ void Connections_HandleSwitchover(connection_id_t connectionId, bool forceSwitch bool connectionIsSelected = SelectedHostConnectionId == connectionId; bool noHostIsConnected = ActiveHostConnectionId == ConnectionId_Invalid; if (hostConnection->switchover || noHostIsConnected || forceSwitch || connectionIsSelected) { - setCurrentDongleToStandby(); + if (connectionId != ActiveHostConnectionId) { + setDongleToStandby(ActiveHostConnectionId); + } switchOver(connectionId); - reportConnectionState(connectionId, "Conn state"); + reportConnectionState(connectionId); } } @@ -440,7 +445,7 @@ void Connections_HandleSwitchover(connection_id_t connectionId, bool forceSwitch for (uint8_t i = ConnectionId_HostConnectionFirst; i <= ConnectionId_HostConnectionLast; i++) { if (Connections[i].state == ConnectionState_Ready) { switchOver(i); - reportConnectionState(i, "Conn state"); + reportConnectionState(i); break; } } diff --git a/device/src/device_state.c b/device/src/device_state.c index 442d208d1..4a89d2b4a 100644 --- a/device/src/device_state.c +++ b/device/src/device_state.c @@ -54,7 +54,7 @@ void handleStateTransition(connection_target_t remote, connection_id_t connectio EventVector_WakeMain(); } - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in handleStateTransition - left was disconnected"); + BtManager_StartScanningAndAdvertisingAsync(false, "handleStateTransition - left was disconnected"); } break; case ConnectionTarget_Host: diff --git a/device/src/keyboard/charger.c b/device/src/keyboard/charger.c index 603c3ffd8..73baa1934 100644 --- a/device/src/keyboard/charger.c +++ b/device/src/keyboard/charger.c @@ -23,7 +23,7 @@ #include "battery_unloaded_calculator.h" #include -LOG_MODULE_REGISTER(Battery, LOG_LEVEL_INF); +LOG_MODULE_REGISTER(Battery, LOG_LEVEL_WRN); /** * chargerStatDt == 1 => (actually) not charging (e.g., fully charged, or no power provided) @@ -134,7 +134,7 @@ static uint16_t getVoltage() { } static void printState(battery_state_t* state) { - printk("Battery is present: %i, charging: %i, charger enabled: %i, powered: %d, at %imV (%i%%); automaton state %d\n", state->batteryPresent, state->batteryCharging, Charger_ChargingEnabled, state->powered, state->batteryVoltage, state->batteryPercentage, currentChargingAutomatonState); + LOG_INF("Battery is present: %i, charging: %i, charger enabled: %i, powered: %d, at %imV (%i%%); automaton state %d\n", state->batteryPresent, state->batteryCharging, Charger_ChargingEnabled, state->powered, state->batteryVoltage, state->batteryPercentage, currentChargingAutomatonState); } void Charger_PrintState() { @@ -158,7 +158,7 @@ static bool handleStateTransition(battery_manager_automaton_state_t newState) { currentChargingAutomatonState = newState; switch (newState) { case BatteryManagerAutomatonState_TurnOff: - // printk("Going to shut down. Measured voltage %d, computed voltage %d, powered %d\n", rawVoltage, batteryState->batteryVoltage, batteryState->powered); + // LOG_INF("Going to shut down. Measured voltage %d, computed voltage %d, powered %d\n", rawVoltage, batteryState->batteryVoltage, batteryState->powered); // PowerMode_ActivateMode(PowerMode_AutoShutDown, false, false); // break; case BatteryManagerAutomatonState_Powersaving: @@ -191,12 +191,12 @@ static bool updateChargerEnabled(battery_state_t *batteryState, battery_manager_ if (voltage > minThreshold) { BatteryManager_SetMaxCharge(newMaxVoltage); oldState = BatteryManagerAutomatonState_Charged; - printk("Charger stopped at %dmV. Setting as new 100%%.\n", voltage); + LOG_INF("Charger stopped at %dmV. Setting as new 100%%.\n", voltage); Charger_PrintState(); } else { BatteryManager_SetMaxCharge(BatteryManager_StandardUse.maxVoltage - 10); oldState = BatteryManagerAutomatonState_Charged; - printk("Charger stopped bellow %dmV. This is suspicious!\n", minThreshold); + LOG_INF("Charger stopped bellow %dmV. This is suspicious!\n", minThreshold); Charger_PrintState(); } } else if (newMaxVoltage > config->maxVoltage) { @@ -324,7 +324,7 @@ void Charger_UpdateBatteryState() { bool actuallyCharging = !gpio_pin_get_dt(&chargerStatDt); stateChanged |= setActuallyCharging(actuallyCharging && Charger_ChargingEnabled); - // printk("Going to measure voltage; charger formallyEnabled = %d, actuallyEnabled = %d, actuallyCharging = %d\n", Charger_ChargingEnabled, actuallyEnabled, actuallyCharging); + // LOG_INF("Going to measure voltage; charger formallyEnabled = %d, actuallyEnabled = %d, actuallyCharging = %d\n", Charger_ChargingEnabled, actuallyEnabled, actuallyCharging); setChargerEnPin(false); @@ -395,7 +395,7 @@ void chargerStatCallback(const struct device *port, struct gpio_callback *cb, gp StateSync_UpdateProperty(StateSyncPropertyId_Battery, &batteryState); } if (Shell.statLog) { - printk("STAT changed to %i\n", stat ? 1 : 0); + LOG_INF("STAT changed to %i\n", stat ? 1 : 0); } EventScheduler_Reschedule(Timer_GetCurrentTime() + CHARGER_STAT_PERIOD, EventSchedulerEvent_UpdateBattery, "charger - stat callback"); } @@ -404,10 +404,10 @@ bool Charger_ShouldRemainInDepletedMode(bool checkVoltage) { updatePowered(); if (checkVoltage) { uint16_t voltage = getVoltage(); - printk("Charger_ShouldRemainInDepletedMode called; powered = %d && raw voltage = %d\n", batteryState.powered, voltage); + LOG_INF("Charger_ShouldRemainInDepletedMode called; powered = %d && raw voltage = %d\n", batteryState.powered, voltage); return !batteryState.powered && voltage > 1000 && voltage < BatteryManager_GetCurrentBatteryConfig()->minWakeupVoltage; } else { - printk("Charger_ShouldRemainInDepletedMode called; powered = %d\n", batteryState.powered); + LOG_INF("Charger_ShouldRemainInDepletedMode called; powered = %d\n", batteryState.powered); return !batteryState.powered; } } @@ -416,7 +416,7 @@ bool Charger_ShouldEnterDepletedMode() { updatePowered(); uint16_t voltage = getVoltage(); - printk("Charger_ShouldEnterDepletedMode called; powered = %d && raw voltage = %d\n", batteryState.powered, voltage); + LOG_INF("Charger_ShouldEnterDepletedMode called; powered = %d && raw voltage = %d\n", batteryState.powered, voltage); return !batteryState.powered && voltage < BatteryManager_GetCurrentBatteryConfig()->minVoltage; } diff --git a/device/src/keyboard/i2c.c b/device/src/keyboard/i2c.c index 435215023..1578a4ce2 100644 --- a/device/src/keyboard/i2c.c +++ b/device/src/keyboard/i2c.c @@ -13,7 +13,8 @@ // Thread definitions -#define THREAD_STACK_SIZE 1000 +// 1000 did overflow +#define THREAD_STACK_SIZE 2000 #define THREAD_PRIORITY -1 static K_THREAD_STACK_DEFINE(stack_area, THREAD_STACK_SIZE); diff --git a/device/src/keyboard/oled/screens/notification_screen.c b/device/src/keyboard/oled/screens/notification_screen.c index 331728fad..e94c18a17 100644 --- a/device/src/keyboard/oled/screens/notification_screen.c +++ b/device/src/keyboard/oled/screens/notification_screen.c @@ -4,6 +4,9 @@ #include "screen_manager.h" #include #include "event_scheduler.h" +#include + +LOG_MODULE_REGISTER(Notify, LOG_LEVEL_INF); static widget_t notificationWidget; @@ -17,7 +20,7 @@ void NotificationScreen_Init(void) { } void NotificationScreen_NotifyFor(const char* message, uint16_t duration) { - printk("Notification: %s\n", message); + LOG_INF("Notification: %s", message); TextWidget_SetText(¬ificationWidget, message); ScreenManager_ActivateScreen(ScreenId_Notification); diff --git a/device/src/keyboard/oled/screens/pairing_screen.c b/device/src/keyboard/oled/screens/pairing_screen.c index fc2b54149..c5c637d41 100644 --- a/device/src/keyboard/oled/screens/pairing_screen.c +++ b/device/src/keyboard/oled/screens/pairing_screen.c @@ -65,6 +65,12 @@ void PairingScreen_Feedback(bool success) } } +void PairingScreen_Cancel(void) +{ + passwordCharCount = 0; + ScreenManager_SwitchScreenEvent(); +} + const rgb_t* PairingScreen_ActionColor(key_action_t* action) { static const rgb_t black = { 0, 0, 0 }; static const rgb_t green = { 0, 0xff, 0 }; diff --git a/device/src/keyboard/oled/screens/pairing_screen.h b/device/src/keyboard/oled/screens/pairing_screen.h index d8643a4c0..f3c84deda 100644 --- a/device/src/keyboard/oled/screens/pairing_screen.h +++ b/device/src/keyboard/oled/screens/pairing_screen.h @@ -24,6 +24,7 @@ void PairingScreen_RegisterScancode(uint8_t scancode); void PairingScreen_AskForPassword(void); void PairingScreen_Feedback(bool success); + void PairingScreen_Cancel(void); const rgb_t* PairingScreen_ActionColor(key_action_t* action); #endif diff --git a/device/src/nus_client.c b/device/src/nus_client.c index 6d02b0f0d..18b4e0884 100644 --- a/device/src/nus_client.c +++ b/device/src/nus_client.c @@ -25,7 +25,7 @@ #include "trace.h" #include -LOG_MODULE_DECLARE(Bt); +LOG_MODULE_REGISTER(NusClient, LOG_LEVEL_INF); static struct bt_nus_client nus_client; @@ -35,7 +35,7 @@ static K_SEM_DEFINE(nusBusy, NUS_SLOTS, NUS_SLOTS); static void ble_data_sent(struct bt_nus_client *nus, uint8_t err, const uint8_t *const data, uint16_t len) { k_sem_give(&nusBusy); if (err) { - LOG_WRN("Bt: ATT error code: 0x%02X\n", err); + LOG_WRN("Bt: ATT error code: 0x%02X", err); } } @@ -66,25 +66,25 @@ static void discovery_complete(struct bt_gatt_dm *dm, void *context) { err = bt_nus_handles_assign(dm, nus); if (err) { - LOG_WRN("Could not assign NUS handles (err %d)\n", err); + LOG_WRN("Could not assign NUS handles (err %d)", err); return; } err = bt_nus_subscribe_receive(nus); if (err) { - LOG_WRN("Could not subscribe to NUS notifications (err %d)\n", err); + LOG_WRN("Could not subscribe to NUS notifications (err %d)", err); return; } err = bt_gatt_dm_data_release(dm); if (err) { - LOG_WRN("Could not release the discovery data (err %d)\n", err); + LOG_WRN("Could not release the discovery data (err %d)", err); return; } - LOG_INF("NUS connection with %s successfully established\n", GetPeerStringByConn(nus->conn)); + LOG_DBG("NUS connection with %s successfully established", GetPeerStringByConn(nus->conn)); if (DEVICE_ID == DeviceId_Uhk80_Right) { Bt_SetConnectionConfigured(Peers[PeerIdLeft].conn); @@ -95,11 +95,11 @@ static void discovery_complete(struct bt_gatt_dm *dm, void *context) { } static void discovery_service_not_found(struct bt_conn *conn, void *context) { - LOG_WRN("Service not found\n"); + LOG_WRN("Service not found"); } static void discovery_error(struct bt_conn *conn, int err, void *context) { - LOG_WRN("Error while discovering GATT database: (%d)\n", err); + LOG_WRN("Error while discovering GATT database: (%d)", err); } struct bt_gatt_dm_cb discovery_cb = { @@ -111,15 +111,15 @@ struct bt_gatt_dm_cb discovery_cb = { static void gatt_discover(struct bt_conn *conn) { int err = bt_gatt_dm_start(conn, BT_UUID_NUS_SERVICE, &discovery_cb, &nus_client); if (err) { - LOG_WRN("could not start the discovery procedure, error code: %d\n", err); + LOG_WRN("could not start the discovery procedure, error code: %d", err); } } static void exchange_func(struct bt_conn *conn, uint8_t err, struct bt_gatt_exchange_params *params) { if (err) { - LOG_WRN("MTU exchange failed with %s (err %u)\n", GetPeerStringByConn(conn), err); + LOG_WRN("MTU exchange failed with %s (err %u)", GetPeerStringByConn(conn), err); } else { - LOG_INF("MTU exchange done with %s\n", GetPeerStringByConn(conn)); + LOG_DBG("MTU exchange done with %s", GetPeerStringByConn(conn)); } } @@ -129,14 +129,14 @@ void NusClient_Connect(struct bt_conn *conn) { exchange_params.func = exchange_func; int err = bt_gatt_exchange_mtu(conn, &exchange_params); if (err) { - LOG_WRN("MTU exchange failed with %s, err %d\n", GetPeerStringByConn(conn), err); + LOG_WRN("MTU exchange failed with %s, err %d", GetPeerStringByConn(conn), err); } gatt_discover(conn); err = bt_scan_stop(); if (err && (err != -EALREADY)) { - LOG_WRN("Stop LE scan failed (err %d)\n", err); + LOG_WRN("Stop LE scan failed (err %d)", err); } } @@ -160,11 +160,11 @@ void NusClient_Init(void) { err = bt_nus_client_init(&nus_client, &init); if (err) { - LOG_WRN("NUS Client initialization failed (err %d)\n", err); + LOG_WRN("NUS Client initialization failed (err %d)", err); return; } - LOG_INF("NUS Client module initialized\n"); + LOG_INF("NUS Client module initialized"); } bool NusClient_Availability(messenger_availability_op_t operation) { @@ -186,7 +186,7 @@ static void send_raw_buffer(const uint8_t *data, uint16_t len) { int err = bt_nus_client_send(&nus_client, data, len); if (err) { k_sem_give(&nusBusy); - LOG_WRN("Client failed to send data over BLE connection (err %d)\n", err); + LOG_WRN("Client failed to send data over BLE connection (err %d)", err); } } @@ -209,7 +209,7 @@ void NusClient_SendMessage(message_t* msg) { } if (bufferIdx + msg->len > MAX_LINK_PACKET_LENGTH) { - LOG_WRN("Message is too long for NUS packets! [%i, %i, ...]\n", buffer[0], buffer[1]); + LOG_WRN("Message is too long for NUS packets! [%i, %i, ...]", buffer[0], buffer[1]); Trace_Printc("E1"); Trace_Printc("r2"); return; diff --git a/device/src/nus_server.c b/device/src/nus_server.c index 669c14be1..d67544a4d 100644 --- a/device/src/nus_server.c +++ b/device/src/nus_server.c @@ -13,7 +13,7 @@ #include #include "bt_manager.h" -LOG_MODULE_DECLARE(Bt); +LOG_MODULE_REGISTER(NusServer, LOG_LEVEL_INF); #define NUS_SLOTS 2 @@ -51,7 +51,7 @@ static void send_enabled(enum bt_nus_send_status status) { if (status == BT_NUS_SEND_STATUS_ENABLED) { // in theory, NUS is ready. In practice, it is once we receive a message from the client. - LOG_INF("NUS peripheral connection is ready.\n"); + LOG_DBG("NUS peripheral connection is ready."); } } @@ -64,11 +64,11 @@ static struct bt_nus_cb nus_cb = { int NusServer_Init(void) { int err = bt_nus_init(&nus_cb); if (err) { - LOG_WRN("Failed to initialize UART service (err: %d)\n", err); + LOG_WRN("Failed to initialize UART service (err: %d)", err); return err; } - LOG_INF("NUS Server module initialized.\n"); + LOG_INF("NUS Server module initialized."); return 0; } @@ -85,7 +85,7 @@ static void send_raw_buffer(const uint8_t *data, uint16_t len, struct bt_conn* c int err = bt_nus_send(conn, data, len); if (err) { k_sem_give(&nusBusy); - LOG_WRN("Failed to send data over BLE connection (err: %d)\n", err); + LOG_WRN("Failed to send data over BLE connection (err: %d)", err); } } @@ -122,7 +122,7 @@ void NusServer_SendMessageTo(message_t* msg, struct bt_conn* conn) { } if (bufferIdx + msg->len > MAX_LINK_PACKET_LENGTH) { - LOG_WRN("Message is too long for NUS packets! [%i, %i, ...]\n", buffer[0], buffer[1]); + LOG_WRN("Message is too long for NUS packets! [%i, %i, ...]", buffer[0], buffer[1]); return; } diff --git a/device/src/state_sync.c b/device/src/state_sync.c index 02c4a12bf..6b3bd0094 100644 --- a/device/src/state_sync.c +++ b/device/src/state_sync.c @@ -36,6 +36,9 @@ #include "versioning.h" #include "event_scheduler.h" #include "macro_events.h" +#include + +LOG_MODULE_REGISTER(StateSync, LOG_LEVEL_INF); #define WAKE(TID) if (TID != 0) { k_wakeup(TID); } @@ -72,10 +75,10 @@ static void wake(k_tid_t tid) { if (tid != 0) { k_wakeup(tid); // if (DEBUG_MODE) { - // LogU("StateSync woke up %p\n", tid); + // LogU("StateSync woke up %p", tid); // } } else if (k_uptime_get_32() > 5000) { - printk("Skipping wake up, tid is 0"); + LOG_INF("Skipping wake up, tid is 0"); } } @@ -425,7 +428,7 @@ static void receiveProperty(device_id_t src, state_sync_prop_id_t propId, const case StateSyncPropertyId_Battery: WIDGET_REFRESH(&StatusWidget); { - printk("Batteries: %d%% %d%% (%d %d)\n" + LOG_INF("Batteries: %d%% %d%% (%d %d)" , SyncLeftHalfState.battery.batteryPercentage, SyncRightHalfState.battery.batteryPercentage , SyncLeftHalfState.battery.batteryVoltage, SyncRightHalfState.battery.batteryVoltage ); @@ -517,11 +520,11 @@ static void receiveProperty(device_id_t src, state_sync_prop_id_t propId, const } break; case StateSyncPropertyId_ZeroDummy: - printk("Received an invalid state sync property message: %d %d %d | %d %d | %d %d %d %d %d\n", data[-5], data[-4], data[-3], data[-2], data[-1], data[0], data[1], data[2], data[3], data[4]); + LOG_INF("Received an invalid state sync property message: %d %d %d | %d %d | %d %d %d %d %d", data[-5], data[-4], data[-3], data[-2], data[-1], data[0], data[1], data[2], data[3], data[4]); break; case StateSyncPropertyId_BatteryStationaryMode: //for both local and remote - printk("Setting battery mode to %d\n", Cfg.BatteryStationaryMode); + LOG_INF("Setting battery mode to %d", Cfg.BatteryStationaryMode); EventScheduler_Schedule(Timer_GetCurrentTime() + 1000, EventSchedulerEvent_UpdateBattery, "state sync"); break; case StateSyncPropertyId_PowerMode: @@ -530,8 +533,8 @@ static void receiveProperty(device_id_t src, state_sync_prop_id_t propId, const } break; default: - printk("Property %i ('%s') has no receive handler. If this is correct, please add a " - "separate empty case...\n", + LOG_ERR("Property %i ('%s') has no receive handler. If this is correct, please add a " + "separate empty case...", propId, prop->name); break; } @@ -926,7 +929,7 @@ void StateSync_Init() { } void StateSync_ResetRightLeftLink(bool bidirectional) { - printk("Resetting left right link! %s\n", bidirectional ? "Bidirectional" : "Unidirectional"); + LOG_INF("Resetting left right link! %s", bidirectional ? "Bidirectional" : "Unidirectional"); StateSync_LeftResetCounter++; if (bidirectional) { invalidateProperty(StateSyncPropertyId_ResetRightLeftLink); @@ -957,7 +960,7 @@ void StateSync_ResetRightLeftLink(bool bidirectional) { void StateSync_ResetRightDongleLink(bool bidirectional) { StateSync_DongleResetCounter++; - // printk("Resetting dongle right link! %s\n", bidirectional ? "Bidirectional" : "Unidirectional"); + // LOG_INF("Resetting dongle right link! %s", bidirectional ? "Bidirectional" : "Unidirectional"); if (bidirectional) { invalidateProperty(StateSyncPropertyId_ResetRightDongleLink); } diff --git a/doc-dev/other/crash_logs.md b/doc-dev/other/crash_logs.md new file mode 100644 index 000000000..c9ad46da9 --- /dev/null +++ b/doc-dev/other/crash_logs.md @@ -0,0 +1,24 @@ +# Crash logs - users + +## Uhk80 + +Crash logs have to be enabled via `set devMode true` in `$onInit` + +## Uhk60 + +Crash logs are enabled by default. However, `set devMode true` is suggested as it enables logging in cases of ESD events. + +(We don't log esd reboots because they are often and these crash logs are significantly more disturbing than a quick reboot.) + +# Developer notes + +In order to fit all our uart applications onto two controllers, we use the async uart driver. Unfortunatelly, the async serial backend is significantly less reliable than the default interrupt backend. Especially it is not available at all during early boot phases. When these log are needed, the interrupt driver has to be used: + +- Comment out pin wiring stuff in device/src/main.c. + +- Comment out this in uhk-80-right.conf: + +``` +# CONFIG_SHELL_BACKEND_SERIAL_API_ASYNC=y +``` + diff --git a/doc-dev/other/testing_scenarios.md b/doc-dev/other/testing_scenarios.md new file mode 100644 index 000000000..c35845506 --- /dev/null +++ b/doc-dev/other/testing_scenarios.md @@ -0,0 +1,49 @@ +Following is a list testing suggestions. Not all have to be tested each time. + +## Bluetooth: + +- Pair ble hid. Unpair. Pair again. Save it into connections. Make sure the Agent doesn't offer saving the same device multiple times. +- When two ble hid devices are paired, test that we can `switchHost` between them. +- When a device is paired, check that we can disconnect it and connect it again - i.e., that the bonding information didn't get corrupted. (Optionally, throw in uhk restart, bluetooth restart, test this with multiple devices.) +- Test that we can switch between two dongles and that their leds light up accordingly. +- Issue `switchHost device` against a device that is not present. `switchHost` to current usb. See that uhk now advertises hid (pairing icon) and that a ble hid host can connect. +- Test that we can add a paired device into the host connections. Try pair and add multiple devices within one Agent session. +- Unpair+pair dongle. (Optionally, let a bluetooth hid active while doing so.) +- Pair two ble hids using `bluetooth pair` while all devices are active. +- Unregistered slot connections: try to add a ble hid without registering it in Agent. Change registered connection count and save the userconfig. Check that the ble hid remaind in the same slot (unless another host connection took that slot - in that case, it should be in the first availalbe slot). +- If moving currently connected device's host connection to another position, check that saving the UserConfig doesn't disconnect it - it should be remapped to the new slot by itself. + +Todos: +- deduplicate and reorder these scenarios. + +Known issues: +- Oob pairing (of the dongle) fails when another device is connected, including a dongle that is *not* connected over usb. +- IRK fails are produced by settings loads (maybe this is the cause of the direct advertising issue though?): +``` +[00:00:32.821,655] bt_hci_core: opcode 0x2027 status 0x12 +[00:00:32.821,655] bt_id: Failed to add IRK to controller +``` + +## Usb suspend: + +In all scenarios make sure that uhk works afterwards. + +Test with a pc and with a mac separately. + +- suspend and wake the pc when connected via usb, via pc's button(s). +- suspend and wake the pc when connected via usb, by tapping any key. +- suspend and wake the pc when connected via usb, by tapping the wake key. +- suspend and wake the pc when connected via ble, via pc's button(s). + +## Troubleshooting: + +- Use the `panic` macro to check that crash logs are generated as expected. (`set devMode true` is needed on uhk80) + +## Macros: + +These are obscure scenarios that are not worth to test often, but may be good to test from time to time. + +- test `oneShot` modifiers with multiple oneShot keys. When keystrokeDelay = 250ms and oneshotTimeout = 5000, you have to see modifiers release only after the oneShot key is pressed. +- test `overlayLayer` - test that overlaid keys are working as expected, are in the right places and that their neighbours didn't get affected. + +- diff --git a/doc-dev/other/zephyr_logging.md b/doc-dev/other/zephyr_logging.md new file mode 100644 index 000000000..3eb11d776 --- /dev/null +++ b/doc-dev/other/zephyr_logging.md @@ -0,0 +1,31 @@ +# Uhk logs + +## Uhk60 + +Uhk 60 has no extensive logging in place. See [crash logging](./crash_logs.md) for crash logging configuration. + +## Uhk80 + +- Launch Agent. +- Go to the About page. +- Click the Agent logo seven times. +- Go to the newly visible "Advanced settings" menu. +- Click on the "Zephyr logging" button. +- Check the "Right half" checkbox. If the left half and/or dongle is affected and connected via USB, check them, too. + +# Agent logs + +You can find Agent logs in the following path: + +- on Linux: `~/.config/uhk-agent/uhk-agent.log` +- on macOS: `~/Library/Logs/uhk-agent/uhk-agent.log` +- on Windows: `%USERPROFILE%\AppData\Roaming\uhk-agent/uhk-agent.log` + +Depending on the issue, you may need to enable additional logging by passing additional commandline arguments. For communication related issues, it is `--log=usb`, valid values are `config | misc | usb | usbOps | all`. Furthermore, you may need to prefix them with multiple groups of `--`, exact count depending on your system and exact Agent build. Resulting command may look as follows: + +``` +./UHK.Agent-9.0.0-linux-x86_64.AppImage -- -- --log=misc,config,usb +``` + + + diff --git a/doc-dev/reference-manual.md b/doc-dev/reference-manual.md index 8c000a940..08d9c2c13 100644 --- a/doc-dev/reference-manual.md +++ b/doc-dev/reference-manual.md @@ -590,7 +590,7 @@ Internally, values are saved in one of the following types, and types are automa Key actions can be parametrized with macro arguments. These arguments can be expanded in two ways: -- `$macroArg.` - in which case they are parsed as a single value. This is the normal and safe variant that prevents context corruption. +- `$macroArg.` - in which case they are parsed as a single value - in the sense of valid macro variable expressions. This is the normal and safe variant that prevents context corruption. Abbreviations, shortcuts, and keys generally are not supported by this variant - use the `&` one. - `¯oArg.` - this variant substitutes the argument into current parser context. These allow substituing any string, including full commands or their parts. This is an experimental feature and might be unsafe in some contexts. Following limitations apply: - the argument bounds must correspond to token bounds in the fully expanded string - the argument cannot span multiple lines diff --git a/right/src/config_parser/parse_host_connection.c b/right/src/config_parser/parse_host_connection.c index d82939d80..dda73b9b9 100644 --- a/right/src/config_parser/parse_host_connection.c +++ b/right/src/config_parser/parse_host_connection.c @@ -7,6 +7,11 @@ #include "config_parser/basic_types.h" #include "host_connection.h" #include "parse_config.h" +#include + +#ifdef __ZEPHYR__ +#include "bt_conn.h" +#endif static parser_error_t parseHostConnection(config_buffer_t* buffer, host_connection_t* hostConnection) { host_connection_type_t hostType = ReadUInt8(buffer); @@ -56,6 +61,44 @@ static parser_error_t parseHostConnection(config_buffer_t* buffer, host_connecti return ParserError_Success; } +static void deduplicateUnregisteredConnections(void) { +#ifdef __ZEPHYR__ + if (ParserRunDry) { + return; + } + + for (uint8_t i = 0; i < SERIALIZED_HOST_CONNECTION_COUNT_MAX; i++) { + host_connection_t* conn = &HostConnections[i]; + + if (conn->type != HostConnectionType_UnregisteredBtHid) { + continue; + } + + for (uint8_t j = 0; j < SERIALIZED_HOST_CONNECTION_COUNT_MAX; j++) { + if (i == j) { + continue; + } + + host_connection_t* other = &HostConnections[j]; + + if (other->type != HostConnectionType_BtHid && + other->type != HostConnectionType_Dongle && + other->type != HostConnectionType_UnregisteredBtHid) { + continue; + } + + if (BtAddrEq(&conn->bleAddress, &other->bleAddress)) { + conn->type = HostConnectionType_Empty; + memset(&conn->bleAddress, 0, sizeof(bt_addr_le_t)); + conn->name = (string_segment_t){ .start = NULL, .end = NULL }; + conn->switchover = false; + break; + } + } + } +#endif +} + parser_error_t ParseHostConnections(config_buffer_t *buffer) { int errorCode; @@ -73,5 +116,7 @@ parser_error_t ParseHostConnections(config_buffer_t *buffer) { ); } + deduplicateUnregisteredConnections(); + return ParserError_Success; } diff --git a/right/src/host_connection.c b/right/src/host_connection.c index 5148c14bd..023dc14e2 100644 --- a/right/src/host_connection.c +++ b/right/src/host_connection.c @@ -16,7 +16,7 @@ #include "bt_manager.h" -#define HOST_CONNECTION_SELECT_TIMEOUT 10000 +#define HOST_CONNECTION_SELECT_TIMEOUT 30000 host_connection_t HostConnections[HOST_CONNECTION_COUNT_MAX] = { [HOST_CONNECTION_COUNT_MAX - 2] = { @@ -83,7 +83,7 @@ void HostConnection_SetSelectedConnection(uint8_t connectionId) { void HostConnection_Unselect() { HostConnection_SetSelectedConnection(ConnectionId_Invalid); - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in HostConnection_Unselect"); + BtManager_StartScanningAndAdvertisingAsync(false, "HostConnection_Unselect"); } static void selectConnection(uint8_t connectionId) { diff --git a/right/src/macros/set_command.c b/right/src/macros/set_command.c index e6411590f..2bd21ee9b 100644 --- a/right/src/macros/set_command.c +++ b/right/src/macros/set_command.c @@ -382,12 +382,12 @@ static macro_variable_t bluetooth(parser_context_t* ctx, set_command_action_t ac ASSIGN_BOOL(Cfg.Bt_AlwaysAdvertiseHid); #if DEVICE_IS_UHK80_RIGHT BtManager_EnterMode(PairingMode_Default, false); - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in set_command - alwaysAdvertiseHid changed"); + BtManager_StartScanningAndAdvertisingAsync(false, "set_command - alwaysAdvertiseHid changed"); #endif } else if (ConsumeToken(ctx, "directedAdvertisingAllowed")) { ASSIGN_BOOL(Cfg.Bt_DirectedAdvertisingAllowed); #ifdef __ZEPHYR__ - BtManager_StartScanningAndAdvertisingAsync(false, "StartScanningAndAdvertisingAsync in set_command - directedAdvertisingAllowed changed"); + BtManager_StartScanningAndAdvertisingAsync(false, "set_command - directedAdvertisingAllowed changed"); #endif } else { Macros_ReportErrorTok(ctx, "Parameter not recognized:"); diff --git a/right/src/stubs.h b/right/src/stubs.h index 6c4c7097d..ee07de6a4 100644 --- a/right/src/stubs.h +++ b/right/src/stubs.h @@ -53,9 +53,6 @@ extern void PairingScreen_Feedback(bool success); extern void StateSync_CheckFirmwareVersions(); extern void StateSync_CheckDongleProtocolVersion(); - extern void Trace(char a); - extern void Trace_Printc(const char *s); - extern void Trace_Printf(const char *fmt, ...); extern void PowerMode_PutBackToSleepMaybe(void); extern void BtAdvertise_DisableAdvertisingIcon(void); extern void NotificationScreen_NotifyFor(const char* message, uint16_t duration); diff --git a/right/src/trace.c b/right/src/trace.c index 04b1da13a..6b5d8af1b 100644 --- a/right/src/trace.c +++ b/right/src/trace.c @@ -1,11 +1,7 @@ #include "trace.h" -#include -#include #include #include "macros/status_buffer.h" #include "trace_reasons.h" -#include "wormhole.h" -#include "event_scheduler.h" #include "logger.h" #include "versioning.h" @@ -17,59 +13,7 @@ #define ProxyLog_IsInPanicMode false #endif -static bool enabled = true; - -#define EXPAND_STRING(BUFFER, MAX_LOG_LENGTH) \ -char BUFFER[MAX_LOG_LENGTH]; \ -{ \ - va_list myargs; \ - va_start(myargs, fmt); \ - BUFFER[MAX_LOG_LENGTH-1] = '\0'; \ - vsnprintf(BUFFER, MAX_LOG_LENGTH-1, fmt, myargs); \ -} - -#define TraceBuffer StateWormhole.traceBuffer.data -#define TraceBufferPosition StateWormhole.traceBuffer.position - -void Trace(char a) { - if (enabled) { - StateWormhole.traceBuffer.eventVector = EventScheduler_Vector; - TraceBuffer[TraceBufferPosition] = a; - TraceBufferPosition = (TraceBufferPosition + 1) % TRACE_BUFFER_SIZE; - } -} - -void Trace_Printf(const char *fmt, ...) { - if (enabled) { - EXPAND_STRING(buffer, TRACE_BUFFER_SIZE); - - for (uint16_t i = 0; i < TRACE_BUFFER_SIZE; i++) { - if (buffer[i] == '\0' || buffer[i] > 126) { - break; - } - if (buffer[i] == '\n') { - Trace(' '); - continue; - } - Trace(buffer[i]); - } - } -} - -void Trace_Printc(const char* s) { - if (enabled) { - for (uint16_t i = 0; s[i] != '\0'; i++) { - if (s[i] == '\0' || s[i] > 126) { - break; - } - if (s[i] == '\n') { - Trace(' '); - continue; - } - Trace(s[i]); - } - } -} +bool Trace_Enabled = true; void Trace_Init(void) { for (uint16_t i = 0; i < TRACE_BUFFER_SIZE; i++) { @@ -85,7 +29,7 @@ void Trace_Init(void) { void Trace_Print(log_target_t additionalLogTargets, const char* reason) { uint16_t iter; - enabled = false; + Trace_Enabled = false; device_id_t targetDeviceId = DEVICE_ID; log_target_t targetInterface = 0; @@ -124,7 +68,7 @@ void Trace_Print(log_target_t additionalLogTargets, const char* reason) { } } - enabled = true; + Trace_Enabled = true; #undef LINE_LENGTH } diff --git a/right/src/trace.h b/right/src/trace.h index a474ef75d..ccdc74f70 100644 --- a/right/src/trace.h +++ b/right/src/trace.h @@ -3,33 +3,58 @@ // Includes: - #include #include - #include "debug.h" + #include + #include + #include "trace_defs.h" #include "logger.h" + #include "wormhole.h" + #include "event_scheduler.h" -// Macros: +// Variables: -#define TRACE_BUFFER_SIZE 256 + extern bool Trace_Enabled; -// Typedefs: +// Macros: - typedef struct { - char data[TRACE_BUFFER_SIZE]; - uint32_t eventVector; - uint16_t position; - } ATTR_PACKED trace_buffer_t; - -// Variables: + #define TraceBuffer StateWormhole.traceBuffer.data + #define TraceBufferPosition StateWormhole.traceBuffer.position + +// Inline functions: + + static inline void Trace(char a) { + if (Trace_Enabled) { + StateWormhole.traceBuffer.eventVector = EventScheduler_Vector; + TraceBuffer[TraceBufferPosition] = a; + TraceBufferPosition = (TraceBufferPosition + 1) % TRACE_BUFFER_SIZE; + } + } + + static inline void Trace_Printc(const char* s) { + if (Trace_Enabled) { + StateWormhole.traceBuffer.eventVector = EventScheduler_Vector; + for (uint16_t i = 0; s[i] != '\0' && s[i] < 127; i++) { + TraceBuffer[TraceBufferPosition] = s[i]; + TraceBufferPosition = (TraceBufferPosition + 1) % TRACE_BUFFER_SIZE; + } + } + } + + static inline void Trace_Printf(const char *fmt, ...) { + if (Trace_Enabled) { + char buffer[TRACE_BUFFER_SIZE]; + va_list args; + va_start(args, fmt); + buffer[TRACE_BUFFER_SIZE-1] = '\0'; + vsnprintf(buffer, TRACE_BUFFER_SIZE-1, fmt, args); + va_end(args); + Trace_Printc(buffer); + } + } // Functions: void Trace_Init(void); - - void Trace(char a); - void Trace_Printf(const char *fmt, ...); - void Trace_Printc(const char* s); - void Trace_Print(log_target_t additionalLogTargets, const char* reason); #endif diff --git a/right/src/trace_defs.h b/right/src/trace_defs.h new file mode 100644 index 000000000..66cac37a5 --- /dev/null +++ b/right/src/trace_defs.h @@ -0,0 +1,21 @@ +#ifndef __TRACE_DEFS_H__ +#define __TRACE_DEFS_H__ + +// Includes: + + #include + #include "debug.h" + +// Macros: + + #define TRACE_BUFFER_SIZE 256 + +// Typedefs: + + typedef struct { + char data[TRACE_BUFFER_SIZE]; + uint32_t eventVector; + uint16_t position; + } ATTR_PACKED trace_buffer_t; + +#endif diff --git a/right/src/usb_commands/usb_command_get_new_pairings.c b/right/src/usb_commands/usb_command_get_new_pairings.c index eb3611def..c4773e03b 100644 --- a/right/src/usb_commands/usb_command_get_new_pairings.c +++ b/right/src/usb_commands/usb_command_get_new_pairings.c @@ -24,7 +24,7 @@ static void bt_foreach_bond_cb(const struct bt_bond_info *info, void *user_data) return; } - if (HostConnections_IsKnownBleAddress(&info->addr) == HostKnown_Registered) { + if (HostConnections_IsKnownBleAddress(&info->addr) != HostKnown_Unregistered) { return; } diff --git a/right/src/usb_commands/usb_command_reenumerate.c b/right/src/usb_commands/usb_command_reenumerate.c index 20ad7d483..10df69289 100644 --- a/right/src/usb_commands/usb_command_reenumerate.c +++ b/right/src/usb_commands/usb_command_reenumerate.c @@ -25,6 +25,8 @@ void Reboot(bool rebootPeripherals) { StateWormhole.wasReboot = true; Trace_Printc("Rebooting..."); #ifdef __ZEPHYR__ + printk("Rebooting..."); + k_sleep (K_MSEC(100)); //let it flush logs if (rebootPeripherals) { if (DEVICE_IS_UHK80_RIGHT) { Messenger_Send2(DeviceId_Uhk80_Left, MessageId_Command, MessengerCommand_Reboot, NULL, 0); @@ -55,8 +57,10 @@ void UsbCommand_Reenumerate(const uint8_t *GenericHidOutBuffer, uint8_t *Generic { StateWormhole_Open(); StateWormhole.wasReboot = true; - Trace_Printc("Rebooting..."); + Trace_Printc("Reenumerating..."); #ifdef __ZEPHYR__ + printk("Reenumerating..."); + k_sleep (K_MSEC(100)); //let it flush logs bootmode_set(BOOT_MODE_TYPE_BOOTLOADER); sys_reboot(SYS_REBOOT_COLD); #else diff --git a/right/src/wormhole.h b/right/src/wormhole.h index 0462ca904..1f2f81da4 100644 --- a/right/src/wormhole.h +++ b/right/src/wormhole.h @@ -7,7 +7,7 @@ #include #include "power_mode.h" #include "macros/status_buffer.h" - #include "trace.h" + #include "trace_defs.h" // Macros: diff --git a/scripts/package.json b/scripts/package.json index 3cd735c0c..16422c78f 100644 --- a/scripts/package.json +++ b/scripts/package.json @@ -18,7 +18,7 @@ "serialport": "^12.0.0", "shelljs": "^0.8.4" }, - "firmwareVersion": "16.1.0", + "firmwareVersion": "16.1.1", "deviceProtocolVersion": "4.17.0", "moduleProtocolVersion": "4.3.0", "dongleProtocolVersion": "1.0.2",